Splunk Search

How to report composite transaction breakdown in terms of total, transaction and application duration averages

Explorer

Given the following log events, how can transaction be used to calculate the average duration of nested overlapping transactions plus duration of the overall transaction to find the total duration.

DT=2018-11-06T11:31:08.844-0800|LogId=TxLog||ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Received|
DT=2018-11-06T11:31:08.846-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|
DT=2018-11-06T11:31:08.846-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Sent|DestId=PI_DB2|MsgNm=PIIISPJ
DT=2018-11-06T11:31:08.961-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Received|DestId=PI_DB2|MsgNm=PIIISPJ|Elapsed=115|
DT=2018-11-06T11:31:08.962-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|
DT=2018-11-06T11:31:08.962-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|
DT=2018-11-06T11:31:08.965-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Sent|DestId=PI_DB2|MsgNm=PIIMSPA|
DT=2018-11-06T11:31:08.966-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Sent|DestId=PI_DB2|MsgNm=PIIBSP|
DT=2018-11-06T11:31:09.078-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Received|DestId=PI_DB2|MsgNm=PIIBSP|Elapsed=110|
DT=2018-11-06T11:31:09.079-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Received|DestId=PI_DB2|MsgNm=PIIMSPA|Elapsed=113|
DT=2018-11-06T11:31:09.080-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Sent|DestId=PI_DB2|MsgNm=PIIYSPB|
DT=2018-11-06T11:31:09.192-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Received|DestId=PI_DB2|MsgNm=PIIYSPB|Elapsed=112|
DT=2018-11-06T11:31:09.193-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Sent|DestId=CWS_DIRECT_TLS|MsgNm=/CWSDIRECT/Restraints/DebitCardDetail|
DT=2018-11-06T11:31:09.257-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|
DT=2018-11-06T11:31:09.258-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Received|DestId=CWS_DIRECT_TLS|MsgNm=/CWSDIRECT/Restraints/DebitCardDetail|Elapsed=64|
DT=2018-11-06T11:31:09.259-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|
DT=2018-11-06T11:31:09.262-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|
DT=2018-11-06T11:31:09.263-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Sent|Elapsed=421|

It's easy enough to see a breakdown using - index=app_log | transaction ProcId DestId MsgNm | stats sum(duration) by ProcId DestId MsgNm. I am yet inexperienced and can't figure out how to organize transaction output to produce the desired results.

0 Karma

Explorer

Adonio, Thank you very much! This is very interesting. How would this work with multiple interleaved records where each session is denoted by ProcId? I am trying to figure out how to modify your answer to report on multiple ProcId groupings.

0 Karma

SplunkTrust
SplunkTrust

maybe like this?

| makeresults count=1
| eval data = "DT=2018-11-06T11:31:08.844-0800|LogId=TxLog||ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Received;;;
DT=2018-11-06T11:31:08.846-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904;;;
DT=2018-11-06T11:31:08.846-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Sent|DestId=PI_DB2|MsgNm=PIIISPJ;;;
DT=2018-11-06T11:31:08.961-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Received|DestId=PI_DB2|MsgNm=PIIISPJ|Elapsed=115;;;
DT=2018-11-06T11:31:08.962-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904;;;
DT=2018-11-06T11:31:08.962-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904;;;
DT=2018-11-06T11:31:08.965-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Sent|DestId=PI_DB2|MsgNm=PIIMSPA;;;
DT=2018-11-06T11:31:08.966-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Sent|DestId=PI_DB2|MsgNm=PIIBSP;;;
DT=2018-11-06T11:31:09.078-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Received|DestId=PI_DB2|MsgNm=PIIBSP|Elapsed=110;;;
DT=2018-11-06T11:31:09.079-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Received|DestId=PI_DB2|MsgNm=PIIMSPA|Elapsed=113;;;
DT=2018-11-06T11:31:09.080-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Sent|DestId=PI_DB2|MsgNm=PIIYSPB;;;
DT=2018-11-06T11:31:09.192-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Received|DestId=PI_DB2|MsgNm=PIIYSPB|Elapsed=112;;;
DT=2018-11-06T11:31:09.193-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Sent|DestId=CWS_DIRECT_TLS|MsgNm=/CWSDIRECT/Restraints/DebitCardDetail;;;
DT=2018-11-06T11:31:09.257-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904;;;
DT=2018-11-06T11:31:09.258-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Received|DestId=CWS_DIRECT_TLS|MsgNm=/CWSDIRECT/Restraints/DebitCardDetail|Elapsed=64;;;
DT=2018-11-06T11:31:09.259-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904;;;
DT=2018-11-06T11:31:09.262-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904;;;
DT=2018-11-06T11:31:09.263-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Sent|Elapsed=421;;;
DT=2018-11-06T11:32:08.844-0800|LogId=TxLog||ProcId=4e66cc75-fe14-4d23-9406-065c7ef28905|TxAct=Request Received;;;
DT=2018-11-06T11:32:08.846-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28905;;;
DT=2018-11-06T11:32:08.846-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef289045TxAct=Request Sent|DestId=PI_DB2|MsgNm=PIIISPJ;;;
DT=2018-11-06T11:32:08.961-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28905|TxAct=Response Received|DestId=PI_DB2|MsgNm=PIIISPJ|Elapsed=115;;;
DT=2018-11-06T11:32:08.962-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28905;;;
DT=2018-11-06T11:32:08.962-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28905;;;
DT=2018-11-06T11:32:08.965-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28905|TxAct=Request Sent|DestId=PI_DB2|MsgNm=PIIMSPA;;;
DT=2018-11-06T11:32:08.966-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28905|TxAct=Request Sent|DestId=PI_DB2|MsgNm=PIIBSP;;;
DT=2018-11-06T11:32:09.078-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28905|TxAct=Response Received|DestId=PI_DB2|MsgNm=PIIBSP|Elapsed=110;;;
DT=2018-11-06T11:32:09.079-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28905|TxAct=Response Received|DestId=PI_DB2|MsgNm=PIIMSPA|Elapsed=113;;;
DT=2018-11-06T11:32:09.080-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28905|TxAct=Request Sent|DestId=PI_DB2|MsgNm=PIIYSPB;;;
DT=2018-11-06T11:32:09.192-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28905|TxAct=Response Received|DestId=PI_DB2|MsgNm=PIIYSPB|Elapsed=112;;;
DT=2018-11-06T11:32:09.193-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28905|TxAct=Request Sent|DestId=CWS_DIRECT_TLS|MsgNm=/CWSDIRECT/Restraints/DebitCardDetail;;;
DT=2018-11-06T11:32:09.257-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28905;;;
DT=2018-11-06T11:32:09.258-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28905|TxAct=Response Received|DestId=CWS_DIRECT_TLS|MsgNm=/CWSDIRECT/Restraints/DebitCardDetail|Elapsed=64;;;
DT=2018-11-06T11:32:09.259-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28905;;;
DT=2018-11-06T11:32:09.262-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28905;;;
DT=2018-11-06T11:33:09.263-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28905|TxAct=Response Sent|Elapsed=421"
| makemv delim=";;;" data 
| mvexpand data
| rename data as _raw
| extract
| eval _time = DT
| rename COMMENT as "the above generates data below is the solution" 
| eval start_time = if(TxAct=="Request",_time,null())
| eval sent_time = if(TxAct=="Request Sent",_time,null())
| eval rec_time = if(TxAct=="Response Received",_time,null())
| eval end_time = if(TxAct=="Response Sent",_time,null())
| eventstats values(start_time) as s_t values(end_time) as e_t by ProcId
| eval s_t_epoch = strptime(s_t, "%Y-%m-%dT%H:%M:%S.%3N%z")
| eval e_t_epoch = strptime(e_t, "%Y-%m-%dT%H:%M:%S.%3N%z")
| eval rec_time_epoch = strptime(rec_time, "%Y-%m-%dT%H:%M:%S.%3N%z")
| eval sent_time_epoch = strptime(sent_time, "%Y-%m-%dT%H:%M:%S.%3N%z")
| eval tot_trans_dur_in_sec = e_t_epoch - s_t_epoch
| stats values(*_time_epoch) as *_time_epoch by tot_trans_dur_in_sec ProcId DestId MsgNm
| eval nested_trans_dur_in_sec = rec_time_epoch - sent_time_epoch
| eventstats sum(nested_trans_dur_in_sec) as tot_nested_trans_dur_in_sec by ProcId

added another ProcId and played a little with timestamp

0 Karma

SplunkTrust
SplunkTrust

hello there,

hope i understood your requirements:
try this search anywhere: (not using transaction)

| makeresults count=1
| eval data = "DT=2018-11-06T11:31:08.844-0800|LogId=TxLog||ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Received;;;
DT=2018-11-06T11:31:08.846-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904;;;
DT=2018-11-06T11:31:08.846-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Sent|DestId=PI_DB2|MsgNm=PIIISPJ;;;
DT=2018-11-06T11:31:08.961-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Received|DestId=PI_DB2|MsgNm=PIIISPJ|Elapsed=115;;;
DT=2018-11-06T11:31:08.962-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904;;;
DT=2018-11-06T11:31:08.962-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904;;;
DT=2018-11-06T11:31:08.965-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Sent|DestId=PI_DB2|MsgNm=PIIMSPA;;;
DT=2018-11-06T11:31:08.966-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Sent|DestId=PI_DB2|MsgNm=PIIBSP;;;
DT=2018-11-06T11:31:09.078-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Received|DestId=PI_DB2|MsgNm=PIIBSP|Elapsed=110;;;
DT=2018-11-06T11:31:09.079-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Received|DestId=PI_DB2|MsgNm=PIIMSPA|Elapsed=113;;;
DT=2018-11-06T11:31:09.080-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Sent|DestId=PI_DB2|MsgNm=PIIYSPB;;;
DT=2018-11-06T11:31:09.192-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Received|DestId=PI_DB2|MsgNm=PIIYSPB|Elapsed=112;;;
DT=2018-11-06T11:31:09.193-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Request Sent|DestId=CWS_DIRECT_TLS|MsgNm=/CWSDIRECT/Restraints/DebitCardDetail;;;
DT=2018-11-06T11:31:09.257-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904;;;
DT=2018-11-06T11:31:09.258-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Received|DestId=CWS_DIRECT_TLS|MsgNm=/CWSDIRECT/Restraints/DebitCardDetail|Elapsed=64;;;
DT=2018-11-06T11:31:09.259-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904;;;
DT=2018-11-06T11:31:09.262-0800|LogId=AppLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904;;;
DT=2018-11-06T11:31:09.263-0800|LogId=TxLog|ProcId=4e66cc75-fe14-4d23-9406-065c7ef28904|TxAct=Response Sent|Elapsed=421"
| makemv delim=";;;" data 
| mvexpand data
| rename data as _raw
| extract
| eval _time = DT
| rename COMMENT as "the above generates data below is the solution" 
| eval start_time = if(TxAct=="Request",_time,null())
| eval sent_time = if(TxAct=="Request Sent",_time,null())
| eval rec_time = if(TxAct=="Response Received",_time,null())
| eval end_time = if(TxAct=="Response Sent",_time,null())
| eventstats values(start_time) as s_t values(end_time) as e_t
| eval s_t_epoch = strptime(s_t, "%Y-%m-%dT%H:%M:%S.%3N%z")
| eval e_t_epoch = strptime(e_t, "%Y-%m-%dT%H:%M:%S.%3N%z")
| eval rec_time_epoch = strptime(rec_time, "%Y-%m-%dT%H:%M:%S.%3N%z")
| eval sent_time_epoch = strptime(sent_time, "%Y-%m-%dT%H:%M:%S.%3N%z")
| eval tot_trans_dur_in_sec = e_t_epoch - s_t_epoch
| stats values(*_time_epoch) as *_time_epoch by tot_trans_dur_in_sec ProcId DestId MsgNm
| eval nested_trans_dur_in_sec = rec_time_epoch - sent_time_epoch
| eventstats sum(nested_trans_dur_in_sec) as tot_nested_trans_dur_in_sec

hope it helps

0 Karma