extract the duration of the records

[tedfong]

Hello,
I would like to ask if I want to extract the duration of the action by each of MCN (earliest begin.action and earliest end...action) from the below log.
is there any expression to do so?

----log----
STAT. [14-01-2015 05:00:00:057] [Thread=413] [ID=ABCD] [MCN=1234] begin.action=action1
STAT. [14-01-2015 05:10:00:063] [Thread=413] [ID=ABCD] [MCN=1234] end...action=action1
STAT. [14-01-2015 05:20:00:057] [Thread=413] [ID=EFGH] [MCN=5678] begin.action=action1
STAT. [14-01-2015 05:30:00:063] [Thread=413] [ID=EFGH] [MCN=5678] end...action=action1
STAT. [14-01-2015 05:40:00:057] [Thread=413] [ID=ABCD] [MCN=1234] begin.action=action1
STAT. [14-01-2015 05:50:00:063] [Thread=413] [ID=ABCD] [MCN=1234] end...action=action1
STAT. [14-01-2015 05:55:00:057] [Thread=413] [ID=EFGH] [MCN=5678] begin.action=action2
STAT. [14-01-2015 05:57:00:063] [Thread=413] [ID=EFGH] [MCN=5678] end...action=action2

[tedfong]

Thans kenth213,
Should be better to use startswith="begin.action" endswith="end...action" , but sometime another ID with MCN will trigger the same action between them. like below. Would the duration count between the line1 and line3 for case 1, count between line 1 and line4??

case1)
STAT. [14-01-2015 05:00:00:057] [Thread=413] [ID=ABCD] [MCN=1234] begin.action=action1
STAT. [14-01-2015 05:10:00:057] [Thread=413] [ID=EFGH] [MCN=5678] begin.action=action1
STAT. [14-01-2015 05:20:00:063] [Thread=413] [ID=EFGH] [MCN=5678] end...action=action1
STAT. [14-01-2015 05:30:00:063] [Thread=413] [ID=ABCD] [MCN=1234] end...action=action1

case2)
STAT. [14-01-2015 05:00:00:057] [Thread=413] [ID=ABCD] [MCN=1234] begin.action=action1
STAT. [14-01-2015 05:10:00:063] [Thread=413] [ID=ABCD] [MCN=1234] end...action=action1
STAT. [14-01-2015 05:20:00:057] [Thread=413] [ID=ABCD] [MCN=1234] begin.action=action1
STAT. [14-01-2015 05:30:00:063] [Thread=413] [ID=ABCD] [MCN=1234] end...action=action1

[kenth213]

When the transaction is made |transaction ID MCN| or | transaction ID MCN startswith="begin.action" endswith="end...action" it grabs the events with the matching fields for ID and MCN

So in case 1 ID and MCN match on lines 1 + 4, and 2 + 3. The duration is calculated from the difference between the first event and last event in the transaction. e.g line 4 time - line 1 time = duration.

Case 2 should match lines 1+2 and 3+4.

You can read more here: http://docs.splunk.com/Documentation/Splunk/6.2.1/SearchReference/transaction

[the_wolverine]

When using transaction, duration is calculated automatically:

sourcetype=source | transaction ID MCN | table _time, ID, MCN, duration

[tedfong]

Thanks you kenth first, However

The below is my expression

sourcetype="source" ID mcn begin.action OR end...action |convert ctime(time) as timestamp| transaction startswith="begin.action" endswith="end...action" | table timestamp ID mcn begin_action end__action duration _raw

i found from
some records are in different ID or MCN or even the begin/ end_action

but i want to extract the duration for same ID, MCN and begin.action/end...action=action1. Is there any improvement for my expression?

STAT. [14-01-2015 05:00:00:057] [Thread=413] [ID=ABCD] [MCN=1234] begin.action=action1
STAT. [14-01-2015 05:10:00:063] [Thread=413] [ID=ABCD] [MCN=1234] end...action=action1

[kenth213]

Updated my answer above. Let me know how it goes.

[kenth213 · Accepted solution]

Hi,

You could try turn the events into a transaction and show the duration of the transaction.

Updated answer based on your comment. Try this:

sourcetype="source" | ID mcn begin.action OR end...action | convert ctime(_time) as timestamp | transaction ID MCN maxspan=30s | table timestamp ID MCN duration

If that doesn't work try adding back in startswith="begin.action" endswith="end...action" after transactioin ID MCN

You can configure maxspan to the maximum duration between the first and last event (currently 30 seconds) i.e. end...action cannot be more than 30 seconds after begin.action. Let me know how it goes.

Cheers