Detect most delay transactions

[indeed_2000]

How can I find most delay transactions?
Here is the log file like below, I want to find which transaction delay and sort them descending, show result in table and subtract time stamp and show in front of transaction

Here is the log:

16:30:53:002 start[C1]L[143]F[10]
16:30:54:002 start[C2]L[143]F[20]
16:30:55:002 start[C5]L[143]F[02]
16:30:56:002 start[C12]L[143]F[30]
16:30:57:002 start[C5]L[143]F[7]
16:30:58:002 end[C1]L[143]F[10]
16:30:59:002 start[C1]L[143]F[11]
16:30:60:002 end[C1]L[143]F[11]

Expected output:

Transaction                               Delay 
16:30:53:002 start[C1]L[143]F[10]            5s 
16:30:58:002 end[C1]L[143]F[10]

16:30:59:002 start[C1]L[143]F[10]            1s 
16:30:60:002 end[C1]L[143]F[10]

...

FYI: 1 sometimes we have start without end, or end without start.
2 “F” means footprints, sometimes “F” it might not be unique, so after first “start” we should expect “end”.

Any recommendation?

Thanks

[manjunathmeti · Accepted solution]

Hi @mehrdad_2000, Try this query:

 | makeresults | eval Transaction="16:30:53:002 start[C1]L[143]F[10],16:30:54:002 start[C2]L[143]F[20],16:30:55:002 start[C5]L[143]F[02],16:30:56:002 start[C12]L[143]F[30],16:30:57:002 start[C5]L[143]F[7],16:30:58:002 end[C1]L[143]F[10],16:30:59:002 start[C1]L[143]F[11],16:31:00:002 end[C1]L[143]F[11]" | makemv delim="," Transaction | mvexpand Transaction | rex field=Transaction "(?<time>[\d:]+)\s(?<status>[\w]+)(?<field>.*)" | eventstats count by field | where count=2 | eval time=strptime(time, "%H:%M:%S:%3N") | delta p=1 time as Delay | eval Delay=if(status="end", Delay, "") | table Transaction, Delay

[indeed_2000]

Thank you this exactly what I want.

[to4kawa]

your search
| rex "(?<time>\S+) (?<status>start|end)(?<id>\[\w+\]L\[\d+\])"
| eval time=strptime(time, "%T:%3Q")
| streamstats count(eval(status="start")) as session by id
| stats list(_raw) as Transaction range(time) as Delay count as flag by session id
| where flag >1
| table Transaction Delay
| eval Delay=tostring(Delay, "duration")

[indeed_2000]

Please use makeresults

[to4kawa]

why? there is your search, isn't it?

[indeed_2000]

No result not work as expected, if makeresults add to it i can describe more precisely here.

[to4kawa]

Is that so,I'm sorry.

[indeed_2000]

Seems group all the result, not separate them two by two that dedicate them bye “start” and “end”.
I think footprint (F) and time stamp might help to separate them two by two.

[to4kawa]

No such thing.

[indeed_2000]

Here is the output

16:30:53:002 start[C1]L[143]F[10]          6s
 16:30:54:002 start[C2]L[143]F[20]
 16:30:55:002 start[C5]L[143]F[02]
 16:30:56:002 start[C12]L[143]F[30]
 16:30:57:002 start[C5]L[143]F[7]
 16:30:59:002 start[C1]L[143]F[11]



16:30:58:002 end[C1]L[143]F[10]       2s
 16:30:60:002 end[C1]L[143]F[11]

[to4kawa]

why another session and id are same multivalue?

[indeed_2000]

Would you please add makeresults in the first below sample, so I can check output, thanks.

16:30:53:002 start[C1]L[143]F[10]
16:30:54:002 start[C2]L[143]F[20]
16:30:55:002 start[C5]L[143]F[02]
16:30:56:002 start[C12]L[143]F[30]
16:30:57:002 start[C5]L[143]F[7]
16:30:58:002 end[C1]L[143]F[10]
16:30:59:002 start[C1]L[143]F[11]
16:30:60:002 end[C1]L[143]F[11]