Getting Data In

Calculating latency based on uuid

smiehe
New Member

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

0 Karma
1 Solution

cpetterborg
SplunkTrust
SplunkTrust

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.

View solution in original post

0 Karma

niketn
Legend

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.

____________________________________________
| makeresults | eval message= "Happy Splunking!!!"
0 Karma

cpetterborg
SplunkTrust
SplunkTrust

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.

0 Karma
Get Updates on the Splunk Community!

Detecting Remote Code Executions With the Splunk Threat Research Team

WATCH NOWRemote code execution (RCE) vulnerabilities pose a significant risk to organizations. If exploited, ...

Enter the Splunk Community Dashboard Challenge for Your Chance to Win!

The Splunk Community Dashboard Challenge is underway! This is your chance to showcase your skills in creating ...

.conf24 | Session Scheduler is Live!!

.conf24 is happening June 11 - 14 in Las Vegas, and we are thrilled to announce that the conference catalog ...