subtraction of timestamp from two search

[jayaraj1717]

i would like to calculate response time by extracting timestamp from two different search then subtracting Response=Send-Received. example search A has timestamp of received and Search B will be having time stamp of Sent. two search interconnected with transctionID. I am using following syntax

But TimeOnrequest always coming as Blank, any suggestion please?

[somesoni2]

Try something like this (assuming there are no duplicate request-response set of events for a TransId

index=TEST Source=Log1  "Request received" OR "Response sent"
|rex field=_raw "DT=(?<DT>.*?) \|"| eval _time=strptime(DT,"%Y-%m-%d %H:%M:%S.%3N")
| rex field=_raw "Type=(?<Type>\w+)"
| chart values(_time) over TransID by Type
| eval _time=Request | eval ResponseTime=Response-Request
| timechart span=15m avg (ResponseTime) AS AvgResponseTime

[niketn]

@jayaraj1717 add the raw events for Request received and Response sent(mask/anonymize any sensitive data if required). Seems like TrasID is the key to correlate the two events. Also while posting code/SPL here on Splunk Answers use the code button 101010 or CTRL+K shortcut key so that special characters do not get escaped. Also what is Field1?

Based on the partial information so far you should try something like following (where TrasID should be a field present in your raw event for both Request and Response to be used as the key for correlation)

Index=TEST Source=Log1 ("Request received" OR "Response sent")
| rex field=_raw "Time (?<_time>\d{4}-\d{1,2}-\d{1,2})\s\d{2}:\d{2}:\d{2}\.\d{3}" 
| eval _time=strptime(_time,"%Y-%m-%d %H:%M:%S.%3N") 
| eval type=if(searchmatch(Request),"Request","Response")
| stats count as eventCount values(type) as type by earliest(_time) as _time latest(_time) as LatestTime by TrasID
| search (type="Request" AND type="Response")
| eval duration=LatestTime-_time
| timechart span=15m avg(duration) AvgDuration

If this does not work please provide further details as requested for the community members to assist.

[jayaraj1717]

Logs Format:

Event1

 DT=2018-05-14T01:17:57.805-0700 |TrasID=Hostname1:processName1:201805140116510739:Uniqnumber1 |Type=Response Sent   | Severity=INFO   ||Main=XXXXXXXXXXXXXXX, Message Timestamp:2018-05-14 01:17:57.641|

 Event2

 DT=2018-05-14T01:17:57.649-0700 |TrasID=Hostname1:processName1:201805140116510739:Uniqnumber1 |Type=Request Received  | Severity=INFO|Main=XXXXXXXXXXXXXXX, Message Timestamp:2018-05-14 01:17:57.641|

Query used:

 Index=TEST Source=Log1 [ search Index=TEST Source=Log1 "Request received"|rex field=_raw "DT=(?<DT>.*?) \|"| eval TimeOnrequest=strptime(DT,"%Y-%m-%d %H:%M:%S.%3N")| fields TrasID ] "Response sent"|rex field=_raw "Message Timestamp:(?<Timestamp>.*?)$" | eval TimeOnresponse=strptime(Timestamp,"%Y-%m-%d %H:%M:%S.%3N")| eval RespseTime=TimeOnresponse-TimeOnrequest|timechart span=15m avg (RespseTime) by ErrorCode

[niketn]

@jayaraj1717, looking at your data seems like TrasID is hostname and will not be the key for correlating event 1 and event 2. It may be considered as composite key.
Should it be processName1? Is Uniqnumber1 unique only for correlated transactions? Is it part of field process1?

[jayaraj1717]

TrasID is composite and have combination of hostname and process along with Uniqnumber1 . yes Uniqnumber1 unique only for correlated transactions. only pair at time have this number(pair meant event1 and 2). same way event3 and 4 will be having diferent unique number combo along with host and process name.

[niketn]

Based on the sample data provided you should try the following search. Since Type=Request Sent or Type=Request Received are delimted by equal-to sign Type should show up in Interesting Fields during Search Time Field discovery (please validate before using Type in the following query)

  index=TEST source=Log1 (Type="Request" OR Type="Response")
 | rex field=_raw "Message Timestamp:(?<Time>[^|]+)\|"
 | rex field= _raw "TrasID=(?<TrasID>[^\s]+)\s\|Type= "
 | eval _time=strptime(_time,"%Y-%m-%d %H:%M:%S.%3N") 
 | stats count as eventCount values(Type) as Type by earliest(_time) as _time latest(_time) as LatestTime by TrasID, process, 
 | search (Type="Request" AND Type="Response")
 | eval duration=LatestTime-_time
 | timechart span=15m avg(duration) AvgDuration

Test the regular expressions on regex101.com : TrasID and Time

[jlelli]

I am not an expert but i think there are some logic problems;
First I would use something simpler to extract the timestamps since _time is already defined in Splunk

Search A | stats last(_time) as Received by transactionID | join transactionID [search B |  stats last(_time) as Send by transactionID] | eval Response=Received-Sent

Now that you got the response time for each specific transationID and I suppose you want to know the avg Response time during specific time slots. however with my system you do not have anymore a general _time but only the one referred to the specific TransactionID. A possible solution would be nest this search as a further subsearch for the time range you need, something like:

Search A | join transactionID [Search A | stats last(_time) as Received by transactionID | join transactionID [search B | stats last(_time) as Send by transactionID] | eval Response=Received-Sent] | stats avg(Response) by _time

I think there are easier ways to achieve this but it should work

[jayaraj1717]

thanks jlelli. actually I would take time from log message if you in my command there are two time one is DT and other is message time both are from different search A and B respectively. in that case above suggestion would not be sufficient.

[jayaraj1717]

Index=TEST Source=Log1 [ search Index=TEST Source=Log1 "Request received"|rex field=_raw "Time (TimeStamp)$"| eval TimeOnrequest=strptime(Timestamp,"%Y-%m-%d %H:%M:%S.%3N")| fields TrasID ] "Response sent"|rex field=_raw "Time (TimeStamp)$"| eval TimeOnresponse=strptime(Timestamp,"%Y-%m-%d %H:%M:%S.%3N")| eval RespseTime=TimeOnresponse-TimeOnrequest|timechart span=15m avg (RespseTime) by Field1