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!

Introducing Splunk Enterprise 9.2

WATCH HERE! Watch this Tech Talk to learn about the latest features and enhancements shipped in the new Splunk ...

Adoption of RUM and APM at Splunk

    Unleash the power of Splunk Observability   Watch Now In this can't miss Tech Talk! The Splunk Growth ...

Routing logs with Splunk OTel Collector for Kubernetes

The Splunk Distribution of the OpenTelemetry (OTel) Collector is a product that provides a way to ingest ...