Splunk Search

Calculating duration in a transaction using a different, not-quite-a-time field.

mahlerrd
Explorer

How can I use a different value to calculate duration than the built-in _time? I have a case where the only accurate timestamps to use for the duration of some events is the difference between the Uptime of the beginning item of a transaction and the ending item of that same transaction.

For instance, given a beginning of "88 days, 01:01:01" and an ending of "88 days, 01:02:03" the duration is 1 minute and 2 seconds. So, I pull out the "days" portion and the time portion of the uptime then (at least for now) stick those two together and convert them with strptime to get a ... well, a consistent timing method. I have to include "days" or else transactions that cross the day boundary would be incorrect.

It would be better to use an entirely separate "duration" that isn't based off any existing timestamp, so that all the plotting and other timing information (comparison with wall clock) stays right.

I know you can fake it out by doing something like

 eval _time=strptime(rt2, "%j:%H:%M:%S") 

Then using duration the regular way, but that breaks wall-clock timing. Heck, it makes things nearly unfindable.

One potential (working) set of search I have at the moment that does everything except this piece is:

host=VNX 
| rex "Uptime: (?P\d+\s)" | rex "days, (?P<rt>\d+:\d+:\d+)" | rex "FAR_(?P<repl_name>[^_]+)"
| eval rt2=trim(rd).":".rt |eval realtime=strptime(rt2, "%j:%H:%M:%S")
| transaction repl_name startswith="starting Incremental copy" endswith="completing Incremental copy"
| fields duration,repl_name

Of course, that's just code I have at the moment, it's gone through many iterations and is a bit messy at the moment. In it, though, I have a "realtime" I can use if I wanted to calculate duration, I just can't figure out how.

Also, I'm not against other solutions. 🙂

(And yes, I know there are all sorts of problems at this time with the code... I'm trying to get it working and can clean it, tweak it or otherwise document oddities (like when the systems involved get rebooted) later. For now, I just need it to work for the past few weeks and perhaps the next few months.)

Tags (2)
0 Karma
1 Solution

mahlerrd
Explorer

OK, thank you both! A different set of eyes with a different set of experience and knowledge behind them helped immensely! While neither answer was the one I needed, they both helped to give me new things to think through. More searching then found the key, which was found here:

http://splunk-base.splunk.com/answers/3651/calculate-diff-between-two-entries-in-a-transaction

mvindex can do what I need once I've made the transaction. Right now, again awfully messy and in need of much cleanup, is the complete code.

host=VNX | rex "Uptime: (?P\d+\s)" | rex "days, (?P\d+:\d+:\d+.\d+)" | rex "FAR_(?P[^_]+)" 
| eval rt2=trim(rd).":".rt |eval realtime=strptime(rt2, "%j:%H:%M:%S.%N")
| transaction repl_name startswith="starting Incremental copy" endswith="completing Incremental copy"
| eval begintime=mvindex(realtime,0) | eval endtime=mvindex(realtime,1) |eval realduration=endtime-begintime
| fields duration,repl_name,realtime,begintime,endtime,realduration

So, in a rather convoluted form, I pull out the fields I need with the regular expressions (oh, I added back in the hundredths of a second), eval them into something unified so they can be converted to something that Splunk's math works on well.

Then create transactions out of those. Using mvindex, set a begintime and endtime via the different indexes into the transaction, then do a simple subtraction...

I now have


duration=1 <-- Notice these aren't right.
realduration=0.120000 <-- but LOOK!
begintime=1369133669.370000

endtime=1369133669.490000

realtime=1369133669.370000

realtime=1369133669.490000

repl_name=Source Mirror DS07

and


duration=0 <-- again, I won't belabor the obvious
realduration=0.140000 <-- Wonderful.
begintime=1369133428.730000

endtime=1369133428.870000

realtime=1369133428.730000

realtime=1369133428.870000

repl_name=Source Mirror DS07


And bonus - the solution won't be bothered by reboots of the storage processors, because they're only used in calculating the difference. (Or, will be as I clean things up).

View solution in original post

mahlerrd
Explorer

OK, thank you both! A different set of eyes with a different set of experience and knowledge behind them helped immensely! While neither answer was the one I needed, they both helped to give me new things to think through. More searching then found the key, which was found here:

http://splunk-base.splunk.com/answers/3651/calculate-diff-between-two-entries-in-a-transaction

mvindex can do what I need once I've made the transaction. Right now, again awfully messy and in need of much cleanup, is the complete code.

host=VNX | rex "Uptime: (?P\d+\s)" | rex "days, (?P\d+:\d+:\d+.\d+)" | rex "FAR_(?P[^_]+)" 
| eval rt2=trim(rd).":".rt |eval realtime=strptime(rt2, "%j:%H:%M:%S.%N")
| transaction repl_name startswith="starting Incremental copy" endswith="completing Incremental copy"
| eval begintime=mvindex(realtime,0) | eval endtime=mvindex(realtime,1) |eval realduration=endtime-begintime
| fields duration,repl_name,realtime,begintime,endtime,realduration

So, in a rather convoluted form, I pull out the fields I need with the regular expressions (oh, I added back in the hundredths of a second), eval them into something unified so they can be converted to something that Splunk's math works on well.

Then create transactions out of those. Using mvindex, set a begintime and endtime via the different indexes into the transaction, then do a simple subtraction...

I now have


duration=1 <-- Notice these aren't right.
realduration=0.120000 <-- but LOOK!
begintime=1369133669.370000

endtime=1369133669.490000

realtime=1369133669.370000

realtime=1369133669.490000

repl_name=Source Mirror DS07

and


duration=0 <-- again, I won't belabor the obvious
realduration=0.140000 <-- Wonderful.
begintime=1369133428.730000

endtime=1369133428.870000

realtime=1369133428.730000

realtime=1369133428.870000

repl_name=Source Mirror DS07


And bonus - the solution won't be bothered by reboots of the storage processors, because they're only used in calculating the difference. (Or, will be as I clean things up).

kristian_kolb
Ultra Champion

If the time info you have in your event ("DD days, HH:MM:SS ") is relative to the event timestamp, you could calculate an absolute point in time for 'your' time info.;

eval begintime = _time - (DD*86400 + HH*3600 + MM*60 + SS) 

You'll need to extract them as fields first of course. Then you do the same for the endtime.

eval my_dur = endtime - begintime

Useful?

/K

aholzer
Motivator

Consider using a join or appendcol instead of a transaction. You can then calculate the "realtime" into two different fields depending if it's your start event time (realtime_start) or your end event time (realtime_end). Then simply do an eval to calc the difference:

| eval difference=realtime_end-realtime_start

and an eval to make that difference more human readable:

| eval difference=strftime(difference,"%d:%H:%M:%S")

Hopefully this helps.

0 Karma
Get Updates on the Splunk Community!

.conf24 | Registration Open!

Hello, hello! I come bearing good news: Registration for .conf24 is now open!   conf is Splunk’s rad annual ...

Splunk is officially part of Cisco

Revolutionizing how our customers build resilience across their entire digital footprint.   Splunk ...

Splunk APM & RUM | Planned Maintenance March 26 - March 28, 2024

There will be planned maintenance for Splunk APM and RUM between March 26, 2024 and March 28, 2024 as ...