Splunk Search
Highlighted

Get duration between two different events in milliseconds

Engager

I am trying to figure out how to get duration returned in milliseconds between two events. Transactions are great to group similar events together but the duration is represented in seconds by default which does not help my use case.

I currently have

* | rex field=_raw "(\"|\')id(\"|\'):\s?(\"|\')event_(?<event_id>[a-z0-9.]+)(\"|\')" | convert timeformat="%3N" mktime(_time) as _time | transaction event_id | search linecount > 1
0 Karma
Highlighted

Re: Get duration between two different events in milliseconds

SplunkTrust
SplunkTrust

Add this to the end of your search to get a millisecond duration from your transaction:

... | eval ms = duration * 1000
0 Karma
Highlighted

Re: Get duration between two different events in milliseconds

Engager

Thanks for the response. My current query returns duration as 0 and 1 while the two event timestamps are:

2014-10-22T20:31:41.223043-04:00

2014-10-22T20:31:41.288006-04:00

diff = 64963 (microseconds)

0 Karma
Highlighted

Re: Get duration between two different events in milliseconds

SplunkTrust
SplunkTrust

In that case I'm guessing your timestamps weren't extracted correctly at index time. Look at the timestamps listed in front of the events when displaying them without the transaction and check if the millisecond part is filled correctly or just three zeroes.

0 Karma
Highlighted

Re: Get duration between two different events in milliseconds

Engager

so I think the problem is because there seems to be two datetimes:

Oct 22 20:31:41 www001.host.dev 2014-10-22T20:31:41.288006-04:00

Looks about right?

0 Karma
Highlighted

Re: Get duration between two different events in milliseconds

SplunkTrust
SplunkTrust

Looks like a syslog event that had a secondary timestamp slapped on somewhere along the line... and by default Splunk will grab the first proper timestamp it finds.

The best thing to do in the long run is to reconfigure the timestamp detection for that sourcetype to have Splunk use the correct one. That's an index-time change though, so it won't work retroactively.

To get a quick win you can extract that timestamp into a field, apply the transaction, and do the maths yourself. Something along these lines:

base search | rex "(?<mytime>\d\d\d\d-\d\d-\d\dT\d\d:\d\d:\d\d.\d{6}(?:\+|-)\d\d:\d\d)" | eval mytimeepoch = strptime(mytime, "%Y-%m-%dT%H:%M:%S.%6N%Z") | transaction event_id | eval myduration = tonumber(mvindex(mytimeepoch, -1)) - tonumber(mvindex(mytimeepoch, 0))

Untested and with ugly field names, but it should work. Basically it extracts its own timestamp, lets the transaction create a multivalued field for that, and subtracts the first value from the last. Make sure that actually grabs the minimum and maximum value though.