Calculate elapsed time from field timestamp

[johnsmithbitter]

I'm new to splunk and I'm trying to calculate the elapsed time between two events 'STARTED & FINISHED' by event_type by context_event. The problem I have is the timestamp is an extracted field and not the _time given by splunk. I've tried various different ways using the support portal but have failed miserably 😄

sourcetype=eventstore | transaction source_event startswith="STARTED" endswith="FINISHED" | eval elapsed=timestamp_event-timestamp_event

This is the event output I get when I run the above query but I can't seem to get it to sum up the elapsed time

03-01-2014 06:55:30, EventLoggerListener , Event=id='3241388266', message='Report1', timestamp=03-01-2014 06:55:30.535 GMT, type='ENRICHMENT', source='IAS', status='STARTED' 03-01-2014 06:55:30 , EventLoggerListener , Event=id='1670471136', message='Report1', timestamp=03-01-2014 06:55:30.544 GMT, type='ENRICHMENT', source='IAS', status='FINISHED'

context_event = Report1
date_event = 03-01-2014
event_id = 1670471136 event_id = 3241388266
event_type = ENRICHMENT
sourcetype = eventstore
status_event = FINISHED status_event = STARTED
timestamp_event = 06:55:30.535 timestamp_event = 06:55:30.544

Thanks in advance!

[johnsmithbitter]

I've tried both options, but resorted to using option 2 as it made things simpler. Thanks for your help Kristian!

[kristian_kolb · Accepted solution]

So I guess that these are the two events that make up the transaction, right?

03-01-2014 06:55:30, EventLoggerListener , Event=id='3241388266', message='Report1', timestamp=03-01-2014 06:55:30.535 GMT, type='ENRICHMENT', source='IAS', status='STARTED' 

03-01-2014 06:55:30 , EventLoggerListener , Event=id='1670471136', message='Report1', timestamp=03-01-2014 06:55:30.544 GMT, type='ENRICHMENT', source='IAS', status='FINISHED'

You have two options;

1) convert the (second) timestamp in each event into a format that is suitable for mathematical operations like subtraction.

2) configure splunk to use the second timestamp (instead of the first) when extracting the _time field.

If the second timestamp (timestamp_event as you call it) is always going to be very close to 'regular' timestamp in the beginning of each event, you should consider option 2, as it's a simpler configuration, and will also let the transaction command calculate the duration automatically. If there can be a significant difference between the first and second timestamp in the events - and if this is important - you should go for option 1. Also, I'm not 100% sure that the duration field that is calculated by the transaction will keep subsecond precision, so you might have to go for the longer version of option 1 below, if your transactions are very short.

For option 1, the you would do like this (assuming that the second timestamp is extracted as timestamp);

your search 
| eval myTime = strptime(timestamp, "%d-%m-%Y %H:%M:%S.%3N %Z") 
| transaction source_event startswith="STARTED" endswith="FINISHED" 
| eval start = mvindex(timestamp,0) 
| eval end = mvindex(timestamp,1) 
| eval duration = end - start

A shorter version, which does not preserve the original _time (but only for the search, the evens are not changed in any way on disk);

your search 
| eval _time = strptime(timestamp, "%d-%m-%Y %H:%M:%S.%3N %Z") 
| transaction source_event startswith="STARTED" endswith="FINISHED" 

now duration is calculated automatically by transaction.

For option 2 you need to edit which timestamp splunk uses when indexing an event, and this is done in props.conf;

[your_sourcetype_here]
TIME_PREFIX = timestamp=

and you can create your searches in the shortest way possible;

your search 
| transaction source_event startswith="STARTED" endswith="FINISHED" 
| table duration

the last table is for illustration purposes.

Hope this helps,

K

EDIT: there seems to be some limit on how many code markups there can be in one post, which screws up the rendering of the page. Tried changing some of them to bold

[johnsmithbitter]

I've tried both options, but resorted to using option 2 as it made things simpler. Thanks for your help Kristian!