How to calculate the difference between two timestamps from the same event?

[chandravadanj]

I need suggestion to write a search query to calculate a difference between the timestamps for the same event. Following is the sample of the event from the file. Each event can have multiple lines, those are not fixed.

1. A = First I want to get the value "2014-10-18T04:10:06.303Z" from the line which contains "GET /search".
2. B = Then I want to read the value "2014-10-18T04:10:06.189Z" from the line which contains "OPTIONS /search"
3. Then Result = A - B. which is in this case will be 114 millisecond.

{"name":"Test API","hostname":"ip-XXX-XX-XX-XX","pid":8453,"level":30,"msg":"Server started running on 9080","time":"2014-10-18T04:07:46.991Z","v":0}
{"name":"Periscope API","hostname":"ip-XXX-XX-XX-XX","pid":8464,"level":30,"msg":"Server started running on 9080","time":"2014-10-18T04:08:50.242Z","v":0}
{"name":"Test API","hostname":"ip-XXX-XX-XX-XX","pid":8469,"level":30,"msg":"Server started running on 8080","time":"2014-10-18T04:09:57.734Z","v":0}
{"name":"Periscope API","hostname":"ip-XXX-XX-XX-XX","pid":8469,"level":30,"msg":"OPTIONS /search/test/cursor/initial/size/1000","time":"2014-10-18T04:10:06.189Z","v":0}
{"name":"Periscope API","hostname":"ip-XXX-XX-XX-XX","pid":8469,"level":30,"msg":"GET /search/test/cursor/initial/size/1000","time":"2014-10-18T04:10:06.303Z","v":0}
{"name":"Periscope API","hostname":"ip-XXX-XX-XX-XX","pid":8469,"level":30,"query":"test","cursor":"initial","return":"_all_fields","queryParser":"simple","size":"1000","msg":"","time":"2014-10-18T04:10:06.309Z","v":0}

[martin_mueller · Accepted solution]

If that's all one big event then there's no need to correlate anything.

Untested, but this should work:

... | rex "OPTIONS /search.*?\"time\"\D+(?<optionsTime>[^\"]+)"
    | rex "GET /search.*?\"time\"\D+(?<getTime>[^\"]+)" 
    | eval diff = strptime(getTime, "%Y-%m-%dT%H:%M:%S.%3N%Z") - strptime(optionsTime, "%Y-%m-%dT%H:%M:%S.%3N%Z")

[chandravadanj]

Thanks a lot! It worked.

[martin_mueller]

Is that entire block of text one Splunk event?

If so, extract both timestamps into two fields, use strptime() to get the epoch timestamp and subtract one from the other.

[chandravadanj]

Yes, the entire block of text is one splunk event.

I need to help on the syntax how to extract those both the timestamps into the two fields. Could you please help me with a sample.

[martin_mueller]

How can those two events be correlated? Start as a human rather than trying to write a search straight away.

[chandravadanj]

Thanks for the replay.

I am not sure how can we correlate them. Is it possible to read the 2 timestamp values for the single log event and get the difference between those to into a variable. We have this log when the process starts and ends. OPTIONS is start time and GET is end time. We need to find out the difference to know the time taken by these step.

LINE 1 in the Event : {"name":"Periscope API","hostname":"ip-XXX-XX-XX-XX","pid":8469,"level":30,"msg":"OPTIONS /search/test/cursor/initial/size/1000","time":"2014-10-18T04:10:06.189Z","v":0}

LINE 2 in the Event : {"name":"Periscope API","hostname":"ip-XXX-XX-XX-XX","pid":8469,"level":30,"msg":"GET /search/test/cursor/initial/size/1000","time":"2014-10-18T04:10:06.303Z","v":0}