topic Re: Get time difference between events in Splunk Search

Get time difference between events

siddharthmis — Tue, 06 Feb 2018 05:58:57 GMT

Hi,

I have events like following (in the sequence of occurrence)-

{"TransactionId":"570978b406264e398d888cd8b49f867d","ParentId":"","RequestId":"24529c4700e942e1ba036f87b0d6080e","Customer":"86c62bf7f6ee4a1ab004e7e33ad9068a","Action":"ExecuteWCFTask/TestRun","Start":"2018-02-05T08:08:42.4689427+00:00","End":"2018-02-05T08:08:42.9378465+00:00","RequestType":3}

{"TransactionId":"570978b406264e398d888cd8b49f867d","ParentId":"24529c4700e942e1ba036f87b0d6080e","RequestId":"c0114983065a45fb83efa433f093ce06","Customer":"86c62bf7f6ee4a1ab004e7e33ad9068a","Action":"ExecuteWCFTaskService/StartTask","Start":"2018-02-05T08:08:42.48456+00:00","End":"2018-02-05T08:08:42.5158124+00:00","RequestType":5}

{"TransactionId":"570978b406264e398d888cd8b49f867d","ParentId":"c0114983065a45fb83efa433f093ce06","RequestId":"0d1438b1e8af4021a7848314f9e88daf","Customer":"86c62bf7f6ee4a1ab004e7e33ad9068a","Action":"TestRun","Start":"2018-02-05T08:08:42.634785+00:00","End":"2018-02-05T09:54:19.5054132+00:00","RequestType":16}

{"TransactionId":"570978b406264e398d888cd8b49f867d","ParentId":"0d1438b1e8af4021a7848314f9e88daf","RequestId":"bb95c271d2ef412d89bebe74f5db4aff","Customer":"86c62bf7f6ee4a1ab004e7e33ad9068a","Action":"UpdateTaskExecutionHistory","Start":"2018-02-05T09:54:48.2226293+00:00","End":"2018-02-05T09:54:48.2382566+00:00","RequestType":5}

The sequence is always the same, i.e. first we have request type 3, then 5, then 16 and then 5.
Request ID of the first event is the parent ID of second.

The Only parameter common in all events in the TransactionId.

In the above example, Event with RequestType 16 was logged almost 106 minutes after event with RequestType 5 was logged.

I need the Customer and Action from the events whose requestType 16 is not received in real-time.

For e.g. If event with request type 5 is logged at 0500 UTC and search is run at 0700 UTC, I would like to get the customer and action of the event whose requestType 16 is still not logged.

I tried something like-

sourcetype=test  TransactionId=* RequestType=3 | eval epocs=strptime(Start, "%Y-%m-%dT%H:%M:%S.%f") | eval epoce=strptime(End, "%Y-%m-%dT%H:%M:%S.%f")  | stats max(_time) as last_time by Customer, TransactionId | eval latency_minutes=((now()-last_time)/60) | convert ctime(last_time) as last_time | fields + Customer, TransactionId, last_time, latency_minutes

But it didn't help.

Re: Get time difference between events

siddharthmis — Tue, 06 Feb 2018 06:02:20 GMT

I think one possible way to find what I am looking for is to get the transactionID of the event with requestType 5 whose requestId is not the parentId of any event.

Re: Get time difference between events

siddharthmis — Wed, 07 Feb 2018 05:21:00 GMT

Can anyone please suggest what can be done?

Re: Get time difference between events

cmerriman — Wed, 07 Feb 2018 13:38:42 GMT

do you basically need to know at the time of your search if all four events have been logged for every transaction? If that's the case, you could just do sourcetype=test TransactionId=*|transaction TransactionId maxspan=1h maxpause=10m|where eventcount<4, if needed you could continue with your
|stats max(_time) as latest_time by Customer, TransactionId.... but this should get you any transaction that didn't reach all four events.
you can also adjust the maxspan/maxpause in the transaction command to suit your needs. There are other arguments available, as well.
https://docs.splunk.com/Documentation/Splunk/7.0.2/SearchReference/Transaction

Re: Get time difference between events

siddharthmis — Thu, 08 Feb 2018 06:22:56 GMT

I ran-

sourcetype=test TransactionId=* |transaction TransactionId maxspan=-1 maxpause=-1 | where (eventcount<3 and eventcount>1)  | stats max(_time) as last_time by Customer, TransactionId | eval latency_minutes=((now()-last_time)/60) | convert ctime(last_time) as last_time | fields + Customer, TransactionId, last_time, latency_minutes

It gave my what I need but a lot of incorrect rows-

It returned the TransactionId - 309fe4177f9f41ba9141de2d1fed71a7 for which raw events were:

{"TransactionId":"309fe4177f9f41ba9141de2d1fed71a7","ParentId":"","RequestId":"941a38abcfe24a64b83417d76b8ce08d","Customer":"Dummy","Action":"ExecuteWCFTask/Check","Start":"2018-02-08T02:07:35.0661083+00:00","End":"2018-02-08T02:07:35.2067272+00:00","RequestType":3}

{"TransactionId":"309fe4177f9f41ba9141de2d1fed71a7","ParentId":"941a38abcfe24a64b83417d76b8ce08d","RequestId":"8bd669290510421faa744def84043357","Customer":"Dummy","Action":"ExecuteWCFTaskService/StartTask","End":"2018-02-08T02:07:35.2067272+00:00","RequestType":5}

{"TransactionId":"309fe4177f9f41ba9141de2d1fed71a7","ParentId":"8bd669290510421faa744def84043357","RequestId":"f03d9c78-6223-4ffe-9e26-76e0ea81b029","Customer":"Dummy","Action":"Check","Start":"2018-02-08T02:07:51.9417927+00:00","End":"2018-02-08T03:40:53.6402105+00:00","RequestType":16}

{"TransactionId":"309fe4177f9f41ba9141de2d1fed71a7","ParentId":"2f15f976e3d54fa6b91872a32c0f60d0","RequestId":"26f038288d2f46a7b88772a9b1402ec3","Customer":"Dummy","Action":"UpdateTaskExecutionHistory","Start":"2018-02-08T03:41:09.4014092+00:00","End":"2018-02-08T03:41:09.4170427+00:00","RequestType":5}

Re: Get time difference between events

siddharthmis — Thu, 08 Feb 2018 06:44:29 GMT

I think it would be good if we can get the transaction details whose RequestType 3 is logged but RequestType 16 is not and the latency minutes.

basically I am looking for long running transactions, RequestType 16 is logged after the transaction is complete, so I have to rely on RequestType 3 for the details.

Re: Get time difference between events

siddharthmis — Mon, 12 Feb 2018 15:31:37 GMT

Any ideas Anyone?

Re: Get time difference between events

siddharthmis — Mon, 12 Feb 2018 15:36:52 GMT

@somesoni2, can you help me out here?

Re: Get time difference between events

somesoni2 — Mon, 12 Feb 2018 19:13:33 GMT

Give this a try

sourcetype=test  TransactionId=* RequestType=3 OR RequestType=5 OR RequestType=16
| stats list(RequestType) as RequestTypes values(Customer) as Customer values(Action) as Action max(_time) as last_time by TransactionId
| where isnull(mvfind(RequestTypes,"16"))
| eval latency_minutes=((now()-last_time)/60) | convert ctime(last_time) as last_time
| fields - RequestTypes

Re: Get time difference between events

siddharthmis — Tue, 13 Feb 2018 08:54:02 GMT

@somesoni2 I tried:

 sourcetype=test  TransactionId=* RequestType=3
 | stats list(RequestType) as RequestTypes values(Customer) as Customer values(Action) as Action max(_time) as last_time by TransactionId
 | where isnull(mvfind(RequestTypes,"16"))
 | eval latency_minutes=((now()-last_time)/60) | convert ctime(last_time) as last_time
 | fields - RequestTypes

It gives the results alongwith many other incorrect rows, reason being for some tranasctions, the order of the RequestType is 16,3,5,5 and 3,16,5,5

I believe we will need to check if for a transaction, we have action "UpdateTaskExecutionHistory" written or not

Re: Get time difference between events

siddharthmis — Wed, 14 Feb 2018 13:47:02 GMT

@somesoni2, maybe something like -

sourcetype=_json source="http:alusta_etw"  Instance=UK4 Action="*ANYERP*" TransactionId=*  RequestType=3 OR RequestType=5 OR RequestType=16   | stats list(RequestType) as RequestTypes values(TenantCode) as TenantCode list(Action) as Actions max(_time) as last_time by TransactionId  | where isnull(mvfind(Actions,"SchedulerTaskHistoryUpdateGatewayService/UpdateTaskExecutionHistory")) | eval latency_minutes=((now()-last_time)/60) | convert ctime(last_time) as last_time  | fields - RequestTypes