Let's say I have a log that containts
We want for the first transaction to be delineated by event 1 to 3 and the second transaction to be delineated by event 5 to 8.
If we use (transaction startswith="starttransaction" endswith="end transaction" my second transaction is delineated by events 6 to 8 instead of 5-8. As a result the duration is shorter than what expected. In other words the starttransaction event proceeding the end transaction event is always being picked whereas we would like for the first "starttransaction" following the end transaction to be picked.
Thank you Martin, unfortuantely I do not have a common element between the events in my transactions. I am trying to measure how long it takes for wpa_supplicant to connect to an AP after it starts scanning. Often it scans for more than once before it connects and as a result many scan-started events are recorded. My reduced data set is something like this
1412026262.159449: wlan2: CTRL-EVENT-SCAN-STARTED <---- start of transaction 1
1412026258.783734: wlan2: CTRL-EVENT-SCAN-STARTED
1412026226.229726: wlan2: CTRL-EVENT-SCAN-STARTED
1412026211.712098: wlan2: CTRL-EVENT-SCAN-STARTED
1412026203.900786: wlan2: CTRL-EVENT-CONNECTED - Connection to e8:ed:f3:10:cd:3f completed [id=0 id_str=] <--- end of transaction 1
1412026188.747661: wlan2: CTRL-EVENT-SCAN-STARTED <---- start of transaction 2
1412026177.658687: wlan2: CTRL-EVENT-SCAN-STARTED
1412026147.650857: wlan2: CTRL-EVENT-CONNECTED - Connection to e8:ed:f3:10:51:2f completed [id=0 id_str=] <--- end of transaction 2
1412026146.463960: wlan2: CTRL-EVENT-SCAN-STARTED <---- start of transaction 3
1412026143.323471: wlan2: CTRL-EVENT-SCAN-STARTED
1412026131.259936: wlan2: CTRL-EVENT-SCAN-STARTED
1412026125.254478: wlan2: CTRL-EVENT-SCAN-STARTED
1412026110.808932: wlan2: CTRL-EVENT-CONNECTED - Connection to e8:ed:f3:10:6e:ff completed [id=0 id_str=] <--- end of transaction 3
1412026109.575031: wlan2: CTRL-EVENT-SCAN-STARTED
1412026105.132968: wlan2: CTRL-EVENT-SCAN-STARTED
1412026089.933802: wlan2: CTRL-EVENT-CONNECTED - Connection to f8:4f:57:66:53:9f completed [id=0 id_str=]
1412026087.472444: wlan2: CTRL-EVENT-SCAN-STARTED
1412026073.058930: wlan2: CTRL-EVENT-SCAN-STARTED
1412026050.153576: wlan2: CTRL-EVENT-CONNECTED - Connection to e8:ed:f3:10:cd:3f completed [id=0 id_str=]
As you see more often than not there are more than one scans before the supplicant connects (the transaction ends)
If I make my transaction to be
then instead of picking the first scan-started event in each transaction it picks up the last scan-started in each transaction and as a result duration of my transactions is much shorter than what I really am interested in measuring.
I think you can do this using streamstats
to count each occurrence of your starting events, using eventstats
to find the starting event with the highest count (i.e., the oldest one), and then include that count as a criteria for startswith
.
For my example search, assume that gField
is the field that contains the common element between your events (like a transaction number, session id, or something like that), and that sField
is a field that you use in your startswith
criteria
... your base search ... | streamstats count by gField sField | eventstats max(count) as sFieldMax by sField | transaction gField startswith="sField=<starting value> count=sFieldOrder" endswith="sField=<ending value>"
Modifying the illustration by @martin_mueller the search would look like this:
| stats count | eval event = "end start start" | makemv event | mvexpand event | eval sField=1 | streamstats count | eval _time = now() - count | eventstats max(count) as mCount by sField | transaction startswith="event=start sField=mCount" endswith="event=end" keepevicted=t
Someone else out there may have a more streamlined approach, but this should do the trick for you.
Where did sFieldOrder came from? (in the first example)
thanks wpreston!
This works! perhaps a flag to consider the earliest startswith event as feature enhancement might be good..
Thank you for your reply Martin perhaps I oversimplified the example here in that the first transaction had a sing start event and the second had two identical start event. The reality is that I have many transactions and each transaction can have one, two or many start events. Tried your suggestion but it did not help.
I believe this search illustrates your question:
| stats count | eval event = "end start start" | makemv event | mvexpand event | streamstats count | eval _time = now() - count | transaction startswith="event=start" endswith="event=end" keepevicted=t
Returns one two-event transaction and one left over "start" event.