Get the time difference between 2 different events based on common fields

[mrafiq17]

I have a log that shows when the particular event was fired

2019-01-14 19:20:21,849 [DEBUG] [c.h.d.s.i.AsynchronousEventPublicationService] Firing data hub event : DataLoadingStartedEvent{actionId=553, feedId=37, poolId=37}

And another log that shows when the event fired event has completed

2019-01-14 19:20:22,029 [DEBUG] [c.h.d.s.i.AsynchronousEventPublicationService] Firing data hub event : DataLoadingCompletedEvent{actionId=553, feedId=37, poolId=37}

There are many similar such events. I need to calculate the time it took to finish based on the actionId and poolId.
Both the start and finish event needs to have the same actionId and poolId.To calculate the finish time we need to find the difference between DataLoadingStartedEvent and DataLoadingCompletedEvent . How can I achieve this?

[nikita_p]

Hi,
You can also achieve this by converting your starttime and endtime into epoch and then you can do the subtraction between them and then you can again convert time to strp format

[bangalorep]

Hello,
You could use the transaction command with the endswith and startwisth options

here's the documentation on transaction with other options you could use to optimize your search
https://docs.splunk.com/Documentation/Splunk/7.2.0/SearchReference/Transaction

[mrafiq17]

Hi bangalorep,

I have tried the transaction command, it's not accurate. I have found that around 60% was correct while other events did have a closing event but still came as events where no closing events existed. Below is the query

** DataLoading*Event | transaction actionId poolId startswith="DataLoadingStartedEvent" endswith="DataLoadingCompletedEvent" keepevicted=true|search closed_txn=0 AND evicted>=0|eval diff=tostring(now()-_time,"duration") | table diff

[bangalorep]

Hello,
If you use the transaction command the duration is automatically calculated. You could search for duration and add it as an interesting field on the list of fields to the left side

[mrafiq17]

Hi,

The duration would not be calculated as the transaction is not complete. Hence I had to find the time difference by deducting current time from the event time.

[bangalorep]

In your search what is this part for? |search closed_txn=0 AND evicted>=0

You could instead run a search like NOT duration = * and the calculate the duration of the remaining events.

[mrafiq17]

Hi somesoni2,
Thank you for the answer.

I have seen multiple pairs. I am getting the duration wrong as there are multiple pairs as I didn't inform earlier. I used the transaction command and I am getting the correct duration.

DataLoading*Event |transaction actionId poolId startswith="DataLoadingStartedEvent" endswith="DataLoadingCompletedEvent"|eval time=(duration/60)|table actionId poolId time

Regarding the partial events, I have noticed that the startedevent has fired while the completedevent is not present. In such cases, I would we need to go an hour earlier and look for the action id along with the poolid for the startedevent and then get the time from completedevent to calculate the duration. I tried subsearch, but I am not able to form a query.

Could you please help?

[somesoni2]

Could you tell more about these events, like, will there be multiple such pair for a specific actionId and poolId, what you want to do if your selected time range includes partial events (e.g. only includes DataLoadingStartedEvent OR DataLoadingCompletedEvent )?

Generally, you'd do something like this (assuming you've setup a field extraction for extraction e.g. eventType=DataLoadingStartedEvent OR DataLoadingCompletedEvent)

index=foo sourcetype=bar eventType=DataLoadingStartedEvent OR eventType=DataLoadingCompletedEvent
| eval startTime=if(eventType=DataLoadingStartedEvent,_time,null())
| eval endTime=if(eventType=DataLoadingCompletedEvent,_time,null())
| stats min(startTime) as startTime max(endTime) as endTime by  actionId poolId  
| eval duration=endTime-startTime