How to calculate duration between an unknown amount of multiple variables in transaction?

[epresson]

Hello,

I am trying to create a report or dashboard which calculates the average duration between events with the word "Irradiation" and "BeamResult received" among other things. Below are two log examples I'm dealing, the search I have constructed, and the resulting chart. I am having trouble calculating the duration between two events because they are multivariables within my transaction with an unknown index. The amount in the multivariable could be anywhere from 1-5. How do I calculate the duration when the amount of variables is changing? In my search below, I use an mvindex for the 0th variable but I would like to calculate the duration for all of the variables, not just the 0th.

Search:

index=logs host=tcr* date_hour<=22 date_hour>=6 AND "trcs.patient_id" OR "beam * is selected" OR "session is closed" OR "trcs.tsm_state=Irradiation" OR "BeamResult Received" OR "pms.correction_applied" OR "bms.irradiation_state=IRRADIATING_MAP" OR "bms.irradiation_state=PREPARING_MAP" |
eval end=if(searchmatch("BeamResult received*"), _time, null())|
eval endcount=if(searchmatch("BeamResult received*"), _time, null())|
eval layercount=if(searchmatch("IRRADIATING_MAP"), _time, null())|
eval start=if(searchmatch("Irradiation"), _time, null()) |
eval beamTimes=if(searchmatch("beam * is selected"),_time,null())|  
eval endtr=if(searchmatch("session is closed"), _time, null()) | 
transaction startswith="patient_id\=" endswith="is closed" maxspan=2h by host| 
search trcs_patient_id!="A141070" trcs_patient_id!="A142388" trcs_patient_id!="A160539" trcs_patient_id!="A170316" trcs_patient_id!="A153361" trcs_patient_id!="A161805" trcs_patient_id!="A161809" "Irradiation" "BeamResult Received" "pms.correction_applied"| 
sort _time|
eval start=mvindex(start,0)|
eval end=mvindex(end,0)|
eval IrrTot=round(end-start)/60|
eval startre=mvindex(beamTimes,1)| 
eval startse=mvindex(beamTimes,0)| 
eval endse=mvindex(beamTimes,1)| 
eval durationTreatment=round((endtr-startre)/60)| 
eval durationSetup=round((endse-startse)/60)|
replace tcr1 with "Treatment Room 1", tcr2 with "Treatment Room 2", tcr3 with "Treatment Room 3" in host|
chart count(durationTreatment) as "Number of Patients Treated", count(endcount) as "Number of Irradiations", count(layercount) as "Number of Layers", eval(round(avg(durationSetup),2)) as "Average Setup Field Duration(Minutes)", eval(round(avg(durationTreatment),2)) as "Average of Duration of All Treatment Fields(Minutes)", eval(round(avg(IrrTot),2)) as "Average Irradiation Duration(Minutes)" by host

Resulting Chart:

host    Number of Patients Treated  Number of Irradiations  Number of Layers    Average Setup Field Duration(Minutes)   Average of Duration of All Treatment Fields(Minutes)    Average Irradiation Duration(Minutes)
Treatment Room 1    110 243 10620   15.80   13.95   2.03
Treatment Room 2    101 219 11718   15.82   16.00   2.66
Treatment Room 3    129 258 11761   14.76   10.74   2.10

Sample Log #1:

2017-03-20 06:49:59,027 [ INFO] {AWT-EventQueue-0} trcs.patient_id
2017-03-20 06:49:59,474 [ INFO] {EMRC Controller Event Queue} beam 1 is selected.
2017-03-20 07:27:36,366 [ INFO] {applicationQueue} pms.correction_applied
2017-03-20 07:28:41,270 [ INFO] {applicationQueue} pms.correction_applied
2017-03-20 07:30:44,040 [ INFO] {EMRC Controller Event Queue} beam 2 is selected.
2017-03-20 07:36:24,070 [ INFO] {AWT-EventQueue-0} trcs.tsm_state=Irradiation
2017-03-20 07:36:24,087 [ INFO] {Application Queue} bms.irradiation_state=PREPARING_MAP
2017-03-20 07:36:26,088 [ INFO] {Application Queue} bms.irradiation_state=IRRADIATING_MAP
2017-03-20 07:36:26,197 [ INFO] {Application Queue} bms.irradiation_state=PREPARING_MAP
2017-03-20 07:36:28,199 [ INFO] {Application Queue} bms.irradiation_state=IRRADIATING_MAP
2017-03-20 07:37:59,098 [ INFO] {Application Queue} BeamResult received. Status : NORMAL  Dose : 3845.860579789275
2017-03-20 07:38:10,579 [ INFO] {EMRC Controller Event Queue} session is closed.

Sample Log #2:

2017-03-20 07:49:33,101 [ INFO] {AWT-EventQueue-0} trcs.patient_id
2017-03-20 07:49:33,909 [ INFO] {EMRC Controller Event Queue} beam 1 is selected.
2017-03-20 07:57:41,999 [ INFO] {applicationQueue} pms.correction_applied
2017-03-20 07:58:43,306 [ INFO] {EMRC Controller Event Queue} beam 3 is selected.
2017-03-20 08:04:13,119 [ INFO] {AWT-EventQueue-0} trcs.tsm_state=Irradiation
2017-03-20 08:04:13,131 [ INFO] {Application Queue}  bms.irradiation_state=PREPARING_MAP
2017-03-20 08:04:15,132 [ INFO] {Application Queue} bms.irradiation_state=IRRADIATING_MAP
2017-03-20 08:04:15,261 [ INFO] {Application Queue} bms.irradiation_state=PREPARING_MAP
2017-03-20 08:04:17,263 [ INFO] {Application Queue} bms.irradiation_state=IRRADIATING_MAP
2017-03-20 08:04:17,563 [ INFO] {Application Queue} bms.irradiation_state=PREPARING_MAP
2017-03-20 08:07:53,099 [ INFO] {Application Queue} BeamResult received. Status : NORMAL  Dose : 1269.5708868915133
2017-03-20 08:08:03,754 [ INFO] {EMRC Controller Event Queue} beam 2 is selected.
2017-03-20 08:12:10,525 [ INFO] {AWT-EventQueue-0} trcs.tsm_state=Irradiation
2017-03-20 08:12:10,545 [ INFO] {Application Queue} bms.irradiation_state=PREPARING_MAP
2017-03-20 08:12:12,547 [ INFO] {Application Queue} bms.irradiation_state=IRRADIATING_MAP
2017-03-20 08:15:23,194 [ INFO] {Application Queue} BeamResult received. Status : NORMAL  Dose : 1266.4040765152415
2017-03-20 08:15:30,311 [ INFO] {EMRC Controller Event Queue} beam 4 is selected.
2017-03-20 08:18:25,517 [ INFO] {applicationQueue} pms.correction_applied
2017-03-20 08:21:10,277 [ INFO] {AWT-EventQueue-0} trcs.tsm_state=Irradiation
2017-03-20 08:21:10,298 [ INFO] {Application Queue} bms.irradiation_state=PREPARING_MAP
2017-03-20 08:21:12,299 [ INFO] {Application Queue} bms.irradiation_state=IRRADIATING_MAP
2017-03-20 08:21:12,441 [ INFO] {Application Queue} bms.irradiation_state=PREPARING_MAP
2017-03-20 08:21:14,442 [ INFO] {Application Queue} bms.irradiation_state=IRRADIATING_MAP
2017-03-20 08:22:38,251 [ INFO] {Application Queue} BeamResult received. Status : NORMAL  Dose : 693.8375995531609
2017-03-20 08:22:45,150 [ INFO] {EMRC Controller Event Queue} session is closed.

[DalJeanis]

I suspect that using the transaction command is complicating your life, but here's a suggestion of how to think about extracting the data. You'll have to add the by fields to the stats command, probably by transaction, since I'm testing with just your two examples. Use the mvraw=true option on the transaction command, so the _raw for the combined transaction will be an mv field that contains all the individual _raw fields from the events, then do something like this...

| appendpipe 
[ 
| rex max_match=0 "(?<StartTime>^[^\[]+) \[ INFO\] \{AWT-EventQueue-0\} trcs.tsm_state=Irradiation" 
| rex max_match=0 "(?<EndTime>^[^\[]+) \[ INFO\] \{Application Queue\} BeamResult received" 
| eval StartTime = strptime(StartTime,"%Y-%m-%d %H:%M:%S,%3Q") 
| eval EndTime = strptime(EndTime,"%Y-%m-%d %H:%M:%S,%3Q")
| eval totCount=mvcount(StartTime)
| appendpipe 
    [| stats avg(StartTime) as avgStartTime, avg(EndTime) as avgEndTime by (identifying fields) 
     | eval avgDuration=avgEndTime-avgStartTime]
| eval totDuration=totCount*avgDuration
| table (identifying fields) avgDuration totDuration totCount
]

You'll also need to take it from there in deciding whether your grand averages need to be weighted-- I've provided for that above, just sum the totDuration and totCount and then divide it out--and what to do about data errors and edge cases (what if there are three StartTime and two EndTime or vice versa).