How to calculate multiple durations within a transaction for event pairs?

[CatherineLiu007]

For the following events, I need to calculate the duration of all stepA to stepB. There are multiple pairs and there is no other step between stepA and stepB. The same for event pair stepC and stepD.

The result should be TotalTime = 11, stepABDuration =3, stepCDDuration =2

20150421 10:20:16 Step=stepStart, Tid=1111
20150421 10:20:17 Step=stepA, Tid=1111
20150421 10:20:18 Step=stepB, Tid=1111
20150421 10:20:19 Step=stepC, Tid=1111
20150421 10:20:20 Step=stepD, Tid=1111
20150421 10:20:21 Step=stepA, Tid=1111
20150421 10:20:22 Step=stepB, Tid=1111
20150421 10:20:23 Step=stepA, Tid=1111
20150421 10:20:24 Step=stepB, Tid=1111
20150421 10:20:25 Step=stepC, Tid=1111
20150421 10:20:26 Step=stepD, Tid=1111
20150421 10:20:27 Step=stepEnd, Tid=1111

---

Tried the following search and no result was returned.

| sort 0 TimeStamp
| streamstats current=f window=1 first(TimeStamp) as prev 
| eval stepABDuration=if(Step="stepB", Timestamp-prev,0) 
| eval stepCDDuration=if(Step="stepD", TimeStamp-prev,0) 
| stats sum(stepABDuration) as stepABDuration by Tid 
| stats sum(stepCDDuration) as stepCDDuration by Tid 
| transaction TId 
| eval TotalTime = duration
| table Tid, TotalTime, stepABDuration, stepCDDuration

---

Also tried the following and only the duration of 1st pair was returned and sum was incorrect.

|sort _time
|delta _time as StepTime p=1
|eventstats sum(eval(if(Step="stepB",StepTime,0))) as StepABTime, 
            sum(eval(if(Step="stepD",StepTime,0))) as StepCDTime by TId
|transaction TId
|eval TotalTime = duration 
|table TotalTime, StepABTime, StepCDTime 

[chimell]

Hi catherine
Note that when you use if () function , you use == and not = equality
Now replace = by == and re run your request

|sort _time
|delta _time as StepTime p=1
|eventstats sum(eval(if(Step=="stepB",StepTime,0))) as StepABTime,
sum(eval(if(Step=="stepD",StepTime,0))) as StepCDTime by TId
|transaction TId
|eval TotalTime = duration
|table TotalTime, StepABTime, StepCDTime
transactionduration

[martin_mueller]

Splunk does allow single-equals-sign-comparisons in the if() expression.

| stats count | eval foo = if(count=0, "yes", "no")

That works fine.

[martin_mueller · Accepted solution]

This works for your sample data:

| stats count | eval text = "20150421 10:20:16 Step=stepStart, Tid=1111
20150421 10:20:17 Step=stepA, Tid=1111
20150421 10:20:18 Step=stepB, Tid=1111
20150421 10:20:19 Step=stepC, Tid=1111
20150421 10:20:20 Step=stepD, Tid=1111
20150421 10:20:21 Step=stepA, Tid=1111
20150421 10:20:22 Step=stepB, Tid=1111
20150421 10:20:23 Step=stepA, Tid=1111
20150421 10:20:24 Step=stepB, Tid=1111
20150421 10:20:25 Step=stepC, Tid=1111
20150421 10:20:26 Step=stepD, Tid=1111
20150421 10:20:27 Step=stepEnd, Tid=1111" | makemv text delim="
" | mvexpand text | rename text as _raw 
| rex "^(?<_time>\S+\s+\S+)" | eval _time = strptime(_time, "%Y%m%d %H:%M:%S") | sort - _time | extract 
| transaction Tid startswith=(Step="stepStart" OR Step="stepA" OR Step="stepC") endswith=(Step="stepEnd" OR Step="stepB" OR Step="stepD") 
| eval {Step}_duration = duration | rename "* *" as *_* | stats sum(*_duration) as *_duration by Tid

Gives me this result:

Tid   stepA_stepB_duration  stepC_stepD_duration  stepEnd_stepStart_duration
1111                     3                     2                          11

Up to line 14 I'm just setting up your sample data, lines 15 and 16 are where the magic happens. First I build micro-transactions, then I assign each duration to its respective pair, and finally sum it all up.

[martin_mueller]

Great to hear!

[martin_mueller]

Could you post a sample log that doesn't work as intended? Makes thinking about what's awry so much easier.

[CatherineLiu007]

Martin, I figured out the problem - somehow the Splunk forwarder created 3 copies of the same events on the server and that messed up the event pairs. The log has no duplicates and not sure how the duplicates got created on server? After switching to a different log file your code worked perfectly. Thanks so much for your help 🙂

[CatherineLiu007]

Martin, thanks so much for your help. The sample code works great. But when I ran the following search with my log file it returned incorrect duration result for stepD_stepC_duration, stepD_stepA_duration, stepC_stepB_duration, stepEnd_stepStart_duration, stepB_stepA_duration, not the intended AB, CD, StartEnd. Any idea what I am missing? Thanks.

source="*PerfMetrics*" 
 | transaction Tid startswith=(Step="stepStart" OR Step="stepA" OR Step="stepC") 
               endswith=(Step="stepEnd" OR Step="stepB" OR Step="stepD") 
 | eval {Step}_duration = duration
 | rename "* *" as *_*
 | stats sum(*_duration) as *_duration by Tid