How to find the duration of individual steps in a transaction search?

[writetosathya]

Hi, I need to find the duration taken by each step of a single transaction.

We are trying to find out the duration of individual "StepId" ** within a single transaction all joined by **"callback" field - i.e there are multiple "stepId" all joined by a single ** "Callback"**

I am trying the below search

** my search **| transaction callback | table callback stepId duration

I am getting the result as cumulative duration of all the steps as a single field - Is there a way to get the duration of individual stepId's?

Below is my Sample Log

10.136.180.249 - - [15/Feb/2017:10:59:59 -0500] "GET /SampleUI/step?stepId=GUID-4-9D91BA9AE27F4EA69856B99F090EC365&sessionId=31474be3-b803-4d71-999f-8fb17c63cb73&displayFormReferenceKey=5e1d1521-932a-4378-a4f3-7628031739f5&sourceUrl=undefined&callback=jQuery1112045955571818351104_1487174397781&_=148717439778 HTTP/1.1" 200 986

10.136.180.249 - - [15/Feb/2017:11:01:03 -0500] "GET /SampleUI/step?stepId=GUID-27-4ABE861B01EB42AAAE034A863CC5A2EE&sessionId=31474be3-b803-4d71-999f-8fb17c63cb73&displayFormReferenceKey=0b8de127-b24d-4ffd-8930-60c3916ce1d0&sourceUrl=undefined&callback=jQuery1112045955571818351104_1487174397781&_=14871743977 HTTP/1.1" 200 3747

10.136.180.249 - - [15/Feb/2017:11:01:05 -0500] "GET /SampleUI/step?stepId=GUID-30-2D27398D62624694849559DDC3C49090&sessionId=31474be3-b803-4d71-999f-8fb17c63cb73&displayFormReferenceKey=e125423c-2ae3-42c6-bcde-acc96255f702&sourceUrl=undefined&callback=jQuery1112045955571818351104_1487174397781&_=14871743977 HTTP/1.1" 200 1628 

10.136.180.249 - - [15/Feb/2017:11:01:06 -0500] "GET /SampleUI/step?stepId=GUID-33-D0987CBE8DAF422A9A71174DFDEF0CF4&sessionId=31474be3-b803-4d71-999f-8fb17c63cb73&displayFormReferenceKey=f5cd1b64-99ea-4637-a9d4-beae474ed4a5&sourceUrl=undefined&callback=jQuery1112045955571818351104_1487174397781&_=14871743977 HTTP/1.1" 200 362

[somesoni2 · Accepted solution]

Give this a try

Fixed type

** my search ** | sort 0 callback _time | delta _time as stepduration | fillnull value="NA" stepduration | transaction callback | table callback stepId stepduration duration

OR (may be faster)

** my search ** | sort 0 callback _time | delta _time as stepduration | stats min(_time) as start list(stepId) as stepId list(stepduration ) as stepduration max(_time) as end by callback | eval duration=end-_time | table callback stepId stepduration duration

Updated

Try this

** my search ** | sort 0 callback _time | streamstats current=f window=1 valeus(_time) as prev_time by callback | eval stepduration=_time-prev_time | transaction callback | table callback stepId stepduration duration

[writetosathya]

Hi Somesh,

Thanks for the quick reply - I tried out both approaches however I am still getting the values in the same format where the duration value is aggregated for all the stepsID's - I wanted to see if we can calculate duration of each of step ID's

Tried doing a transaction with both fields like

** my search **| transaction callback stepId | table callback stepId duration - does not work as well

can you please guide?

[somesoni2]

The first option has a missing stepduration field in the last table. I've updated it so try again.

Also try the 3rd option that I put. If it still doesn't work, tell me if you see valid values in the field stepduration for following query.

** my search ** | table _time callback stepId | sort 0 callback _time | streamstats current=f window=1 valeus(_time) as prev_time by callback | eval stepduration=_time-prev_time 

[writetosathya]

Somesh,

Thanks a lot for your valuable time - I really appreciate it! - I am getting the split now

There seems to be a data mismatch though- This is the result set I am getting from the query

GUID-27-4ABE861B01EB42AAAE034A863CC5A2EE --- 1
GUID-30-2D27398D62624694849559DDC3C49090 --- 2
GUID-33-D0987CBE8DAF422A9A71174DFDEF0CF4 --- 64
GUID-4-9D91BA9AE27F4EA69856B99F090EC365

However the time duration if I do a manual calculation is

GUID-33-D0987CBE8DAF422A9A71174DFDEF0CF4

GUID-27-4ABE861B01EB42AAAE034A863CC5A2EE --- 2
GUID-30-2D27398D62624694849559DDC3C49090 --- 1
GUID-4-9D91BA9AE27F4EA69856B99F090EC365 --- 64

As this is a web access log and hence the times we have captured as stepduration is actually be the time for the step immediately previous to that .

I understand that you have already given your valuable time so I will try my best to figure what could be skewing the results I am a splunk newbie 🙂 .

Thanks.

[somesoni2]

Ok.. the transaction command is sorting both the mv field, so the order is skewed. You basically need to merge stepduration calculation logic of option 3 with transaction calculation of option 2. Like this

** my search ** | sort 0 callback _time | streamstats current=f window=1 valeus(_time) as prev_time by callback | eval stepduration=coalesce(_time-prev_time,"NA") | | stats min(_time) as start list(stepId) as stepId list(stepduration ) as stepduration max(_time) as end by callback | eval duration=end-_time | table callback stepId stepduration duration

[writetosathya]

Hi somesh,

Thanks for your help again- This one worked 🙂

Again appeciate your guidance,