How to calculate duration in seconds between two events?

[sunnyparmar]

Hi,

I have a log file in which there are two events "Sending reply for message" and "reply message sent". Both are sharing the same time stamp in logs in this format (mm-dd hh:mm:ss). Now I want to calculate the age in seconds between these two events. My search is something like this:

index="abc" sourcetype="xyz" | transaction startswith="Sending reply for message" endswith="reply message sent" | table host duration _time

which is giving the result like given below

host        duration       _time
sc-pet-cif   0   2015-08-31 21:50:37
sc-pet-cif   0   2015-08-31 21:48:30 

It is giving by host, but I want to show the both calculated events in the output with the duration, not host, so please help me out.

Thanks

[sunnyparmar]

Below given is the sample data in which you can see that "Sending reply for message" and "reply message sent" both have sharing the same timestamp so after subtraction the both events timestamp duration will be 0 but I need these both events to come in output.

DEBUG [main] 09-08 12:30:26 Sending reply for message mail box: xyz@basware.com, sender: abc@basware.com, subject: Email Fetcher Performance Testing <<< c...
DEBUG [main] 09-08 12:30:26 validating velocity Template path... (Sending.java:508)
DEBUG [main] 09-08 12:30:26 reply message sent. (Sending.java:392)

My query is something like this

index="abc" sourcetype="xyz" | transaction startswith="Sending reply for message" endswith="reply message sent" | table host duration _time

and the output is given below but as you see I want to include both the events in output that is not coming currently so could you please suggest something for this. thanks

 host         duration        _time
 sc-pet-cif      0      2015-08-31 21:50:37
 sc-pet-cif      0      2015-08-31 21:48:30 

[woodcock]

We can manufacture a sessionID using streamstats like this:

index="abc" sourcetype="xyz" | reverse | eval new_session=if(match(_raw,"Sending reply for message"),"TRUE",null()) | streamstats current=t count(new_session) AS sessionID BY host

Now each host's events have a sessionID field that can be used to distinguish/group events that can be exploited by tacking on something like this:

| stats earliest(_raw) AS first latest(_raw) AS last earliest(_time) AS start latest(_time) AS stop BY host sessionID | eval durationSeconds = stop - start | table host durationSeconds first start last stop 

Any time that you can avoid transaction, you should; it is very slow/costly to use it.

[sunnyparmar]

Sorry for replying late. If i am running your first query it is giving me the result given below

9/8/15 8:05:19.000 PM DEBUG [main] 09-08 14:35:19 whiteList.getEmailAccount().toLowerCase(): abc@bscs.basware.com (MailFetcherDatabaseProcessor.java:118)
9/8/15 8:05:19.000 PM DEBUG [main] 09-08 14:35:19 Successfully loaded MailFetcher 'WhiteList' from database (MailFetcherDatabaseProcessor.java:120)

but didn't get that where is the Session ID generating in the above given output and if i am running your second query by combining with the first one, i am getting the below output

host start stop durationSeconds
hostname 1434603838 1434603844 6

It is not the exact the output what i am want. I want the duration in seconds after subtracting the two events i.e. "Sending reply for message" and "reply message sent" where as in your query you have mentioned only one event that is "Sending reply for message". Please advise.

Thanks

[woodcock]

Based on your new clarification, I have revised my answer (again). I think it will give you what you are trying to get.

[sunnyparmar]

thanks for replying but still not getting the exact result but anyhow I got the answer by Dennis and it is fulfilled my requirement. Regards

[diogofgm]

can you post some sample data?

[somesoni2]

You're getting two events in the output means you're transaction is not being applied. WHat is the expected output?

[diogofgm]

i believe that transaction is being applied. the OP said both events share the same timestamp. that why the duration of the transaction is 0 and for the looks of it, he has 2 transactions. the table command is just showing host duration _time and not the rest of the _raw

[sunnyparmar]

I want both the events name in output. The output generated from my above given query, giving the exact duration after subtracting the time between two events but instead of host i want to show the events name in output so how could I do that?

[somesoni2]

Then you would need to extract the file EventName to contain these string and then show them in the table. To help you with that, please post some sample data.

[sunnyparmar]

Sorry for replying late.. Below given is the data in which you can see that "Sending reply for message" and "reply message sent" both have sharing the same timestamp so after subtraction the both events timestamp duration will be 0 but I need these both events to come in output.

DEBUG [main] 09-08 12:30:26 Sending reply for message mail box: xyz@basware.com, sender: abc@basware.com, subject: Email Fetcher Performance Testing <<< c...
DEBUG [main] 09-08 12:30:26 validating velocity Template path... (Sending.java:508)
DEBUG [main] 09-08 12:30:26 reply message sent. (Sending.java:392)

Thanks

[DennisMohn]

If you want to see the transaction time (which actually is 0 in your example, you can output the raw results with the command
... | table _raw, duration
This will give you both events and the transaction duration.

[sunnyparmar]

Thanks a lot Dennis... It works..

[DennisMohn]

Glad I could help you!