Splunk Search

How to calculate the duration of a single event?

Explorer

Please bear with me as I’m sure this is very simple. I’ve seen examples here of calculating duration for a transaction with multiple log events, but this one has the start and end times in a single event.

alt text
In the above example, I’ve tried

|eval  myduration=STIN_END_DTM-STIN_BEG_DTM

And

|concurrency duration=STIN_END_DTM-STIN_BEG_DTM

both which take the command without error but does not create a duration field.

Please be gentle in telling me what I’m missing! Thanks.

0 Karma
1 Solution

Legend

try

mysearch | eval STIN_END_DTM=strptime(STIN_END_DTM, "%b %d %Y %H:%M:%S:%3N%P"), STIN_BEG_DTM=strptime(STIN_BEG_DTM, "%b %d %Y %H:%M:%S:%3N%P")| eval duration=STIN_END_DTM - STIN_BEG_DTM| table STIN_BEG_DTM STIN_END_DTM duration

with the examples you inserted you'll have

STIN_BEG_DTM         STIN_END_DTM        duration
1474254451.276000   1474254451.290000   0.014000

Bye.
Giuseppe

View solution in original post

Legend

try

mysearch | eval STIN_END_DTM=strptime(STIN_END_DTM, "%b %d %Y %H:%M:%S:%3N%P"), STIN_BEG_DTM=strptime(STIN_BEG_DTM, "%b %d %Y %H:%M:%S:%3N%P")| eval duration=STIN_END_DTM - STIN_BEG_DTM| table STIN_BEG_DTM STIN_END_DTM duration

with the examples you inserted you'll have

STIN_BEG_DTM         STIN_END_DTM        duration
1474254451.276000   1474254451.290000   0.014000

Bye.
Giuseppe

View solution in original post

Explorer

ah yes it was the colon vs the dot for millisconds. Took me forever to find that.

Wow, great catch. Thanks to @MuS and @cusello! Great job.

0 Karma

SplunkTrust
SplunkTrust

Hi johnoke,

your STIN_END_DTM and STIN_BEG_DTM are strings and not numeric values, therefore Splunk cannot calculate a duration with them. You need to strptime() them first and use the resulting epoch to calculation the duration:

  your base search here 
  | eval STIN_END_DTM=strptime(STIN_END_DTM, "%b %d %Y %H:%M:%S.%3N%P"), STIN_BEG_DTM=strptime(STIN_BEG_DTM, "%b %d %Y %H:%M:%S.%3N%P")
  | eval duration=STIN_END_DTM - STIN_BEG_DTM

Take a look at the docs http://docs.splunk.com/Documentation/Splunk/6.4.3/SearchReference/Commontimeformatvariables#Date_var... for more details on the Date and time format variables.

Hope this helps ...

cheers, MuS

Explorer

That makes perfect sense and I've tried several variations of the above, all to no effect. it simply ignores the resulting field, so I assume a conversion error is still happening. Is that error logged somewhere? I couldn't find it on the server (ironic?). Or a debug option to see where it's failing?

The reserved fields date_hour, date_minute and date_second are fine and can be used in an eval. But this isn't cutting it for whatever reason.
... | eval EVAL-myfield1 = strptime(STINBEGDTM,"%b %d %Y %I:%M:%S.%3N%P")

Thanks again.

0 Karma

SplunkTrust
SplunkTrust

Can you please provide some real world samples of your events as text not as screen shot?

0 Karma

Explorer

Thanks so much for pointing out the original issue and docs. %M:%S:%3N%P worked.

0 Karma

Explorer

I set up a field extraction (maybe that's the problem?) like this. I took the defaults after highlighting the 2 TransactionStart,TransactionEnd fields. I re-imported the sample below and the field extracts appear to work well.

EXTRACT- TransactionStart,TransactionEnd
Owner admin
App search
Permissions Owner App All apps
Source type SAMPLE_CMLU
Sample event

00007103-FFA4-4BF7-BB30-D3EE3F83807D|93075237|438A0E3E-CA6A-4320-8ABB-C7C7F40DBDD7|Processing|EADJ|Sep 19 2016  4:41:58:003PM|Sep 19 2016  4:41:59:390PM|cmcaclcl.cpp|2511|CMC_APP_CLAIMS_BASE::SetStatTime|cmcaclcl.cpp|2540|CMC_APP_CLAIMS_BASE::SetStatTime|E|1|Jan  1 1753 12:00:00:000AM
Fields Transaction_Start,Transaction_End

Regular Expression

^(?:[^\|\n]*\|){5}(?P[^\|]+)\|(?P[^\|]+)

My search is this:

host= | eval T_Start=strptime(Transaction_Start, "%b %d %Y %I:%M:%S.%3N%P"), T_End=strptime(Transaction_End, "%b %d %Y %I:%M:%S.%3N%P")

TStart and TEnd are not displayed.

It won't let me attach a file due to my karma deficiency, but here's a copy/paste of a few rows of data.

00002A81-A2E6-4F0C-BBE0-157D8CF8F2B1|93075229|BC433907-71D5-4F58-9135-F4E10FC5F066|XSQL.POSTSAVE|EXTM|Sep 19 2016  3:28:33:936PM|Sep 19 2016  3:28:34:060PM|ceraxmgr.cpp|652|CER_EXIT_MGR::CallExit|ceraxmgr.cpp|654|CER_EXIT_MGR::CallExit|E|1|Jan 1 1753 12:00:00:000AM 00002B07-4AF8-4CBF-97DD-03DF217D5952|93075275|CBAA78E2-4FB5-453C-B0B0-5D12AF04DEA6|XSQL.POSTSAVE|EXTM|Sep 19 2016  4:04:49:823PM|Sep 19 2016  4:04:49:933PM|ceraxmgr.cpp|652|CER_EXIT_MGR::CallExit|ceraxmgr.cpp|654|CER_EXIT_MGR::CallExit|E|1|Jan 1 1753 12:00:00:000AM 00006119-1E3E-4636-8596-0C8F9F85F57F|93075175|255A972F-9DCD-4676-9D07-A640BC53A2A0|XSQL.POSTSAVE|EXTM|Sep 19 2016  2:32:31:646PM|Sep 19 2016  2:32:31:706PM|ceraxmgr.cpp|652|CER_EXIT_MGR::CallExit|ceraxmgr.cpp|654|CER_EXIT_MGR::CallExit|E|1|Jan 1 1753 12:00:00:000AM 00007103-FFA4-4BF7-BB30-D3EE3F83807D|93075237|438A0E3E-CA6A-4320-8ABB-C7C7F40DBDD7|Processing|EADJ|Sep 19 2016  4:41:58:003PM|Sep 19 2016  4:41:59:390PM|cmcaclcl.cpp|2511|CMC_APP_CLAIMS_BASE::SetStatTime|cmcaclcl.cpp|2540|CMC_APP_CLAIMS_BASE::SetStatTime|E|1|Jan 1 1753 12:00:00:000AM 0000884A-F7F1-475C-9691-EEFAFA08AFD1|93075167|                                    |Electronic Claim|EADJ|Sep 19 2016  4:57:15:016PM|Sep 19 2016  4:58:30:610PM|cmcaclcl.cpp|2511|CMC_APP_CLAIMS_BASE::SetStatTime|cmcaclcl.cpp|2540|CMC_APP_CLAIMS_BASE::SetStatTime|E|1|Jan 1 1753 12:00:00:000AM 0000A99A-87A3-41AB-8D4C-93DEBCD490BE|93075237|90321E52-5EF1-4E7B-B2F7-40CB60BCF248|PRESAVE|EXTT|Sep 19 2016  3:11:16:863PM|Sep 19 2016  3:11:17:160PM|ceraxmgr.cpp|562|CER_EXIT_MGR::CallExits|ceraxmgr.cpp|600|CER_EXIT_MGR::CallExits|E|1|Jan 1 1753 12:00:00:000AM 0000C487-7A06-44B5-B2ED-33C2C590A0A4|93075211|AD666596-797D-4385-8EFB-B9EB0A10322C|PRESAVE|EXTT|Sep 19 2016  1:35:02:923PM|Sep 19 2016  1:35:03:000PM|ceraxmgr.cpp|562|CER_EXIT_MGR::CallExits|ceraxmgr.cpp|600|CER_EXIT_MGR::CallExits|E|1|Jan 1 1753 12:00:00:000AM 0000C66E-EA51-4924-B862-36C9A946FC2D|93075207|B8260148-8FFD-4522-80A1-AB9B65255552|XSQL.POSTSAVE|EXTM|Sep 19 2016  2:24:34:376PM|Sep 19 2016  2:24:34:423PM|ceraxmgr.cpp|652|CER_EXIT_MGR::CallExit|ceraxmgr.cpp|654|CER_EXIT_MGR::CallExit|E|1|Jan 1 1753 12:00:00:000AM 0000E31F-A5DF-4207-B7B5-E33A13D4D9BD|93075175|F7C77CEB-00DA-4888-9551-68878576AE0E|POSTSAVE|EXTT|Sep 19 2016  1:59:42:586PM|Sep 19 2016  1:59:42:786PM|ceraxmgr.cpp|562|CER_EXIT_MGR::CallExits|ceraxmgr.cpp|600|CER_EXIT_MGR::CallExits|E|1|Jan 1 1753 12:00:00:000AM 0001151F-C540-4EE5-871A-69CC4EEC0881|93075267|797E20D7-C2CB-4F0C-9678-3DF66A0C562D|XSQL.POSTSAVE|EXTM|Sep 19 2016  2:23:10:956PM|Sep 19 2016  2:23:10:986PM|ceraxmgr.cpp|652|CER_EXIT_MGR::CallExit|ceraxmgr.cpp|654|CER_EXIT_MGR::CallExit|E|1|Jan 1 1753 12:00:00:000AM 00012937-948A-452F-A542-261F8C77FDEF|93075275|8225051D-67EB-4C4A-BBB5-0E13F6B0764E|POSTSAVE|EXTT|Sep 19 2016  5:02:13:290PM|Sep 19 2016  5:02:13:366PM|ceraxmgr.cpp|562|CER_EXIT_MGR::CallExits|ceraxmgr.cpp|600|CER_EXIT_MGR::CallExits|E|1|Jan 1 1753 12:00:00:000AM

Thanks!

0 Karma