Calculating latency based on uuid

[smiehe]

I'm trying to calculate request times for a web app to analyze latency. When a user clicks a button in the client UI, I save the time stamp and push that to Splunk (client_timestamp). When the server receives the request it writes a spunk log entry. So event timestamp minus client_timestamp gives me one piece. However, when the server receives the request, it does a few other things before it responds to the client. So when the client receives a response we also log that (action="response_received"). I basically want to find the diff between when the user clicked the UI and when the UI received the signal to write the action="response_received" log.

[1500700837] location="Germany", device_name="Device A", request_uuid="000412fc-23b9-4882-8241-31482e1987fa", client_timestamp="1500700835936", session_id="8d2c288374d51b6b052e3f03d037b3ca"
[1500700837] location="Germany", device_name="Device B", request_uuid="7ad4b1ca-397a-46a6-8bf2-3e97864ffd45", client_timestamp="1500700835936", session_id="5ca03696a0e19c2b89a189e7534ff0b5"
[1500673343] type="frontend", action="response_received", request_uuid="000412fc-23b9-4882-8241-31482e1987fa", client_timestamp="1500673347109", session_id="8d2c288374d51b6b052e3f03d037b3ca"
[1500700837] location="Canada", device_name="Device C", request_uuid="7ad4b1ca-397a-46a6-8bf2-3e97864ffd45", client_timestamp="1500700835936", session_id="030799a2-9a15-4995-ba1b-04908e1b726b"
[1500673343] type="frontend", action="response_received", request_uuid="7ad4b1ca-397a-46a6-8bf2-3e97864ffd45", client_timestamp="1500673347109", session_id="8d2c288374d51b6b052e3f03d037b3ca"

I essentially want to filter out all the events where not exactly two entries with the same request_uuid exists. Something like:

sourcetype=latency_logs | stats count by request_uuid

Now for all where request_uuid exists 2 times, I'd like to take the client_timestamp from the event that has action="response_received" and subtract it from the other event with the same request_uuid.

Any suggestions how to achieve this? The final result would be a list of request_uuids and their client_timestamp diff

[niketn]

Following should give you duration between request and response. If there are more than two events for a particular request_uuid and session_id, then min(client_timestamp) should give you request time and max(client_timestamp) should give you response time. You can also try first() and last() instead of min() and max().

sourcetype=latency_logs  session_id=* (device_name="Device *" OR action="response_received")
| stats count as eventcount min(client_timestamp) as requestTime max(client_timestamp) as responseTime values(device_name) as device_name values(action) as action by request_uuid, session_id
| where eventcount=2 AND isnotnull(action)
| eval duration = responseTime - requestTime 

PS:
- Your transaction seems to be a combination of request_uuid and session_id so I have used both in stats query.
- Your last example seems to be having request_uuid from second last event and session_id from first event. Seems confusing or maybe incorrect.
- You can use fieldformat on requestTime and responseTime to show Time in Human readable format and also capture values(location) as location to show location information in final result.

[cpetterborg · Accepted solution]

This should work for those with exactly two with the same request_uuid:

sourcetype=latency_log | transaction request_uuid | search linecount=2 | eval latency=tonumber(mvindex(client_timestamp,1))-tonumber(mvindex(client_timestamp,0)) | table request_uuid, latency

If you want to get it for those with 3 or more, as well, then that is not much more difficult:

sourcetype=latency_log | transaction request_uuid | search linecount>1 | eval cnt=tonumber(mvcount(client_timestamp)) | eval latency=tonumber(mvindex(client_timestamp,cnt-1))-tonumber(mvindex(client_timestamp,0)) | table request_uuid, latency

And if you need to make sure that you only count the ones with a response_received in case you have some that have not yet been completed, but there are more than one with the same request_uuid, use:

sourcetype=latency_log | transaction request_uuid | search linecount>1 | search response_received | eval cnt=tonumber(mvcount(client_timestamp)) | eval latency=tonumber(mvindex(client_timestamp,cnt-1))-tonumber(mvindex(client_timestamp,0)) | table request_uuid, latency

I hope this would answer all additional questions, in case you need more refined results.