Getting Data In
Highlighted

Calculating latency based on uuid

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 (clienttimestamp). When the server receives the request it writes a spunk log entry. So event timestamp minus clienttimestamp 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="responsereceived"). 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="responsereceived" log.

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

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

sourcetype=latencylogs | stats count by requestuuid

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

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

0 Karma
Highlighted

Re: Calculating latency based on uuid

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
Highlighted

Re: Calculating latency based on uuid

Legend

Following should give you duration between request and response. If there are more than two events for a particular requestuuid and sessionid, then min(clienttimestamp) should give you request time and max(clienttimestamp) 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 requestuuid and sessionid so I have used both in stats query.
- Your last example seems to be having requestuuid from second last event and sessionid 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.




| eval message="Happy Splunking!!!"


0 Karma