Hi
I am collecting events of states of devices, a device is supposed to be go from the state "false"=beginning of transaction to "true"=end of transactions. I would like to retrieve the duration of my transactions, to track the long/unfinished ones.
My problem is that my logs doesn't always contains the end of transactions event.
Here is an example of my logs. I added comments at the end of the events. you can see that the same device/store pair may starts several transactions without finishing them all.
Thu Mar 31 10:56:26 PDT 2011 Device=1 Store=1 Status=false detail=transaction 1 OK start Thu Mar 31 11:56:26 PDT 2011 Device=1 Store=1 Status=true detail=transaction 1 OK end Thu Mar 31 12:00:26 PDT 2011 Device=1 Store=1 Status=false detail=transaction 2 broken start Thu Mar 31 12:30:26 PDT 2011 Device=1 Store=1 Status=false detail=transaction 3 OK start Thu Mar 31 12:40:26 PDT 2011 Device=1 Store=1 Status=true detail=transaction 3 OK end Thu Mar 31 13:56:26 PDT 2011 Device=1 Store=1 Status=false detail=transaction 4 broken start Thu Mar 31 14:56:26 PDT 2011 Device=1 Store=1 Status=false detail=transaction 5 broken start Thu Mar 31 15:56:26 PDT 2011 Device=1 Store=1 Status=false detail=transaction 6 OK start Thu Mar 31 16:56:26 PDT 2011 Device=1 Store=1 Status=true detail=transaction 6 OK end Thu Mar 31 17:04:26 PDT 2011 Device=1 Store=1 Status=false detail=transaction 7 broken start Thu Mar 31 17:10:26 PDT 2011 Device=1 Store=1 Status=false detail=transaction 8 start - unfinished yet
I would like to retrieve :
This is hard but doable :
The difficult points are :
The solution is to run 2 searches and append the result :
At the end the useful fields to display are : Store, Device, duration, valid_txn, id_txn
source="*transaction.log" true OR false | eval valid_txn="valid" | eval id_txn=Device+"-"+Store+"-"+_time | transaction Device,Store startswith=false endswith=true keepevicted=false maxevents=2 mvlist=true | append maxout=100000 timeout=6000 maxtime=6000 [ search source="*transaction.log" false | eval valid_txn="invalid" | eval id_txn=Device+"-"+Store+"-"+_time | eval tempid_txn=Device+"-"+Store | streamstats range(_time) as duration window=2 by tempid_txn ] | eval id_txn=mvindex(id_txn,0) | dedup id_txn | eval duration=if(duration=0,now()-_time,duration) | eval raw=_raw | table id_txn, Device, Store, duration, Status, closed_txn, valid_txn, raw | sort duration
voila !
To provide another simplified example to count the duration of unfinished transactions
events :
2012-06-20 20:00:00.000 uniqueid=22 state=start
2012-06-20 21:00:00.000 uniqueid=22 state=end
2012-06-20 22:00:00.000 uniqueid=23 state=start
* | transaction uniqueid startswith="state=start" endswith="state=end" keeporphans=true
| eval duration_sec=if(isnull(duration),now()-_time,duration)
| eval status=if(closed_txn==1,"completed","still in progress")
| table _time duration_sec status _raw
We are keeping the orphean transactions and manually calculate the duration from first event to now().
Remarks :
This is hard but doable :
The difficult points are :
The solution is to run 2 searches and append the result :
At the end the useful fields to display are : Store, Device, duration, valid_txn, id_txn
source="*transaction.log" true OR false | eval valid_txn="valid" | eval id_txn=Device+"-"+Store+"-"+_time | transaction Device,Store startswith=false endswith=true keepevicted=false maxevents=2 mvlist=true | append maxout=100000 timeout=6000 maxtime=6000 [ search source="*transaction.log" false | eval valid_txn="invalid" | eval id_txn=Device+"-"+Store+"-"+_time | eval tempid_txn=Device+"-"+Store | streamstats range(_time) as duration window=2 by tempid_txn ] | eval id_txn=mvindex(id_txn,0) | dedup id_txn | eval duration=if(duration=0,now()-_time,duration) | eval raw=_raw | table id_txn, Device, Store, duration, Status, closed_txn, valid_txn, raw | sort duration
voila !
the valid_txn column is important to inform that the duration is valid, or based on estimations.