Splunk Search

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

crisjnelson
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

crisjnelson
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

adonio
Ultra Champion

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

adonio
Ultra Champion

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
Get Updates on the Splunk Community!

Index This | I am a number, but when you add ‘G’ to me, I go away. What number am I?

March 2024 Edition Hayyy Splunk Education Enthusiasts and the Eternally Curious!  We’re back with another ...

What’s New in Splunk App for PCI Compliance 5.3.1?

The Splunk App for PCI Compliance allows customers to extend the power of their existing Splunk solution with ...

Extending Observability Content to Splunk Cloud

Register to join us !   In this Extending Observability Content to Splunk Cloud Tech Talk, you'll see how to ...