Splunk Search

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

CatherineLiu007
Explorer

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 
1 Solution

martin_mueller
SplunkTrust
SplunkTrust

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.

View solution in original post

chimell
Motivator

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
0 Karma

martin_mueller
SplunkTrust
SplunkTrust

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

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

That works fine.

0 Karma

martin_mueller
SplunkTrust
SplunkTrust

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.

View solution in original post

martin_mueller
SplunkTrust
SplunkTrust

Great to hear!

0 Karma

martin_mueller
SplunkTrust
SplunkTrust

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

0 Karma

CatherineLiu007
Explorer

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
Explorer

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
0 Karma
.conf21 Now Fully Virtual!
Register for FREE Today!

We've made .conf21 totally virtual and totally FREE! Our completely online experience will run from 10/19 through 10/20 with some additional events, too!