Splunk Search

Get duration between two different events in milliseconds

tmelios
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

martin_mueller
SplunkTrust
SplunkTrust

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

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

martin_mueller
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.

martin_mueller
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

tmelios
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

tmelios
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
Get Updates on the Splunk Community!

Get Inspired! We’ve Got Validation that Your Hard Work is Paying Off

We love our Splunk Community and want you to feel inspired by all your hard work! Eric Fusilero, our VP of ...

What's New in Splunk Enterprise 9.4: Features to Power Your Digital Resilience

Hey Splunky People! We are excited to share the latest updates in Splunk Enterprise 9.4. In this release we ...

Take Your Breath Away with Splunk Risk-Based Alerting (RBA)

WATCH NOW!The Splunk Guide to Risk-Based Alerting is here to empower your SOC like never before. Join Haylee ...