CODEWITHSUNDEEP
splunk
Kurt Peek
Kurt Peek

Reputation: 57591

How to show the time difference between two events in a Splunk join query?

Consider the following log data,

{"level":"info","msg":"Enqueued a recurring task","time":"2022-04-01T18:46:22.854684-07:00","uuid":"4e9fc098-f611-4128-ae0b-2e6b9cb232c8"}
{"level":"info","msg":"Reported a result","path":"/results","time":"2022-04-01T18:46:22.955999-07:00","uuid":"4e9fc098-f611-4128-ae0b-2e6b9cb232c8"}
{"level":"info","msg":"Reported a result","path":"/results","time":"2022-04-01T18:46:23.056295-07:00","uuid":"4e9fc098-f611-4128-ae0b-2e6b9cb232c8"}
{"level":"info","msg":"Enqueued a recurring task","time":"2022-04-01T18:46:23.056376-07:00","uuid":"28e9bea9-5d0c-4dd5-af4f-c22944fc4fcd"}

It represents enqueuing a recurring task with a certain uuid, the results of which can be reported multiple times (or not at all) with the same uuid. I'm interested in determining the interval elapsed between when the task was enqueued and when the result was reported for the first time. So far, I can display the results this outer join table,

msg="Enqueued a recurring task" 
| join type=outer left=L right=R where L.uuid = R.uuid 
    [ search msg="Reported a result" | dedup uuid sortby +_time] 
| fillnull value="" 
| table _time, L.msg, L.uuid, R.msg, L.time, R.time

enter image description here

What I'd like for convenience is to add an additional column with the difference between R.time and L.time. As far as I can tell from how to calculate duration between two events Splunk, one way to do this is to use strptime to convert those time fields into time values and then determine their difference. However, the time of the events was already parsed when importing the data (as seen from the built-in _time field) so this seems inefficient to me. Is there a more efficient way?

Update

Even the 'inefficient' method using strptime is proving tricky; I've added eval fields t to each of the searches,

msg="Enqueued a recurring task" 
| eval t=strptime(time, "%Y-%m-%dT%H:%M:%S.%6N%:z") 
| join type=outer left=L right=R where L.uuid = R.uuid 
    [ search msg="Reported a result" 
    | dedup uuid sortby +_time 
    | eval t=strptime(time, "%Y-%m-%dT%H:%M:%S.%6N%:z")]
| fillnull value="" 
| table _time, L.msg, L.uuid, R.msg, L.time, R.time, L.t, R.t, R.t-L.t

and it appears to parse the time correctly, yet the difference R.t-L.t shows up empty in the table: enter image description here Any idea why it's not showing the difference?

Update 2

I've tried both of RichG's answers, but they both lead to the following error in Splunk:

Error in 'eval' command: Type checking failed. '-' only takes numbers.

(See screenshots below). The way I'm running Splunk is with a Docker container,

docker run -p 8000:8000 -e "SPLUNK_START_ARGS=--accept-license" -e "SPLUNK_PASSWORD=supersecret" --name splunk splunk/splunk:latest

enter image description here

The second one leads to the error

Update 3

I finally got this to work using RichG's updated answer, combining both an evaluated strftime field with a diff field where R.t and L.t are quoted:

msg="Enqueued a recurring task" 
| eval t=strptime(time, "%Y-%m-%dT%H:%M:%S.%6N%:z") 
| join type=outer left=L right=R where L.uuid = R.uuid 
    [ search msg="Reported a result" 
    | dedup uuid sortby +_time 
    | eval t=strptime(time, "%Y-%m-%dT%H:%M:%S.%6N%:z")]
| fillnull value="" 
| eval diff='R.t'-'L.t'
| table _time, L.msg, L.uuid, R.msg, L.time, R.time, L.t, R.t, diff

enter image description here

Upvotes: 2

Views: 9922

Answers (2)

RichG
RichG

Reputation: 9926

The time difference is empty in the table because the table command does not perform arithmetic. You must calculate the difference in a separate eval and display the result in the table.

index=foo msg="Enqueued a recurring task" 
| eval t=strptime(time, "%Y-%m-%dT%H:%M:%S.%6N%:z") 
| join type=outer left=L right=R where L.uuid = R.uuid 
    [ search index=foo msg="Reported a result" 
    | dedup uuid sortby +_time 
    | eval t=strptime(time, "%Y-%m-%dT%H:%M:%S.%6N%:z")]
| fillnull value="" 
| eval diff='R.t' - 'L.t'
| table _time, L.msg, L.uuid, R.msg, L.time, R.time, L.t, R.t, diff

You should be able to use each event's _time field to avoid having to parse the time field.

index=foo msg="Enqueued a recurring task" 
| join type=outer left=L right=R where L.uuid = R.uuid 
    [ search index=foo msg="Reported a result" 
    | dedup uuid sortby +_time ]
| fillnull value="" 
| eval diff='R._time' - 'L._time'
| table _time, L.msg, L.uuid, R.msg, L.time, R.time, L.t, R.t, diff

Upvotes: 3

warren
warren

Reputation: 33453

Fairly confident something akin to this should work (without using join:

index=ndx sourtype=srctp uuid=* msg=*
| stats min(_time) as first_time max(_time) as last_time earliest(msg) as first_msg latest(msg) as last_msg by uuid
| eval diff_seconds=last_time-first_time
| eval first_time=strftime(first_time,"%c"), last_time=strftime(last_time,"%c")

This approach will presume that _time has been set properly in the sourcetype's props.conf, but if it has, this gets you what you're looking for in one pass.

Upvotes: 1

Related Questions