Splunk Search

How to search the average time between request and response when a certain field value is the same?

saradachelluboy
Explorer

Hi All,

Can someone please help me to calculate the time difference between the request and response when the token is the same?
Because its multi threading between request and response, other request and response can exists, so I want to calculate based on time, request and response when token/thread is same. I have bolded the fields

INFO | 2016-06-09 04:37:29,432 | thread-1 | ApiProviderImpl | request: Transaction Bundle{
INPUT[CLIENTID=10000111;JVM_VERSION=1.7.0_21;TOKEN=11;] OUTPUT[]}
INFO | 2016-06-09 04:37:29,542 |thread-2 | ApiProviderImpl | request: Transaction Bundle{
INPUT[CLIENTID=10000112;JVM_VERSION=1.7.0_21;TOKEN=22;] OUTPUT[]}
INFO | 2016-06-09 04:37:30,415 | thread-1 | ApiProviderImpl | response: Transaction Bundle{
INPUT[CLIENTID=10000111;JVM_VERSION=1.7.0_21;TOKEN=11;]

Regards,
Sarada

0 Karma
1 Solution

MuS
Legend

Hi saradachelluboyena,

try this stats command to get the duration in seconds (this assumes you have a field called thread already) :

INFO thread=* TOKEN=* request OR response 
| stats latest(_time) AS latest earliest(_time) AS earliest by TOKEN, thread 
| eval duration = latest - earliest 

Hope this helps ...

cheers, MuS

Update:

Since you have transaction in your log which are not done yet, you can change the search a bit and use streamstats to get an additional new id field and check against this.
I used this as source file to test it:

INFO | 2016-06-09 04:31:29,432 | thread-1 | ApiProviderImpl | request: Webpay Transaction Bundle{ INPUT[CLIENTID=10000111;JVM_VERSION=1.7.0_21;TOKEN=72;] OUTPUT[]}
INFO | 2016-06-09 04:32:29,542 |thread-2 | ApiProviderImpl | request: Webpay Transaction Bundle{ INPUT[CLIENTID=10000112;JVM_VERSION=1.7.0_21;TOKEN=91;] OUTPUT[]}
INFO | 2016-06-09 04:33:29,542 |thread-3| ApiProviderImpl | response: Webpay Transaction Bundle{ INPUT[CLIENTID=10000113;JVM_VERSION=1.7.0_21;TOKEN=91;] OUTPUT[]}
INFO | 2016-06-09 04:34:29,542 |thread-2 | ApiProviderImpl | request: Webpay Transaction Bundle{ INPUT[CLIENTID=10000112;JVM_VERSION=1.7.0_21;TOKEN=19;] OUTPUT[]}
INFO | 2016-06-09 04:35:29,542 |thread-3| ApiProviderImpl | response: Webpay Transaction Bundle{ INPUT[CLIENTID=10000113;JVM_VERSION=1.7.0_21;TOKEN=19;] OUTPUT[]}
INFO | 2016-06-09 04:36:30,415 | thread-1 | ApiProviderImpl | response: Webpay Transaction Bundle{ INPUT[CLIENTID=10000111;JVM_VERSION=1.7.0_21;TOKEN=72;]
INFO | 2016-06-09 04:37:29,542 |thread-2 | ApiProviderImpl | request: Webpay Transaction Bundle{ INPUT[CLIENTID=10000112;JVM_VERSION=1.7.0_21;TOKEN=20;] OUTPUT[]}
INFO | 2016-06-09 04:38:29,542 |thread-2 | ApiProviderImpl | request: Webpay Transaction Bundle{ INPUT[CLIENTID=10000112;JVM_VERSION=1.7.0_21;TOKEN=21;] OUTPUT[]}

You can see that the last two transactions have started but are not yet finished. Also I created a field called action which has the value of either request or response
Using this as search source you can run the search like this:

TOKEN=* request OR response 
| streamstats earliest(_time) AS earliest latest(_time) AS latest count(eval(if(action="request" OR action="response", 1, null()))) AS id by TOKEN 
| eval diff=latest-earliest 
| where id>1 | table id TOKEN action _time earliest latest 

and the result looks like this:

removed on request
As you can see the last two TOKEN will not show up in this search 😉

cheers, MuS

View solution in original post

sundareshr
Legend

Assuming you have the Token field extracted, the easiest way would to use the transaction command ...

    .... | transaction TOKEN startswith=request endswith=response | table TOKEN duration | eval duration=tostring(duration, "duration")

If you do not have the TOKEN field extracted, add this before the transaction command

   ... | rex "TOKEN=(?<TOKEN>\w+);" | transaction ...
0 Karma

MuS
Legend

Hi saradachelluboyena,

try this stats command to get the duration in seconds (this assumes you have a field called thread already) :

INFO thread=* TOKEN=* request OR response 
| stats latest(_time) AS latest earliest(_time) AS earliest by TOKEN, thread 
| eval duration = latest - earliest 

Hope this helps ...

cheers, MuS

Update:

Since you have transaction in your log which are not done yet, you can change the search a bit and use streamstats to get an additional new id field and check against this.
I used this as source file to test it:

INFO | 2016-06-09 04:31:29,432 | thread-1 | ApiProviderImpl | request: Webpay Transaction Bundle{ INPUT[CLIENTID=10000111;JVM_VERSION=1.7.0_21;TOKEN=72;] OUTPUT[]}
INFO | 2016-06-09 04:32:29,542 |thread-2 | ApiProviderImpl | request: Webpay Transaction Bundle{ INPUT[CLIENTID=10000112;JVM_VERSION=1.7.0_21;TOKEN=91;] OUTPUT[]}
INFO | 2016-06-09 04:33:29,542 |thread-3| ApiProviderImpl | response: Webpay Transaction Bundle{ INPUT[CLIENTID=10000113;JVM_VERSION=1.7.0_21;TOKEN=91;] OUTPUT[]}
INFO | 2016-06-09 04:34:29,542 |thread-2 | ApiProviderImpl | request: Webpay Transaction Bundle{ INPUT[CLIENTID=10000112;JVM_VERSION=1.7.0_21;TOKEN=19;] OUTPUT[]}
INFO | 2016-06-09 04:35:29,542 |thread-3| ApiProviderImpl | response: Webpay Transaction Bundle{ INPUT[CLIENTID=10000113;JVM_VERSION=1.7.0_21;TOKEN=19;] OUTPUT[]}
INFO | 2016-06-09 04:36:30,415 | thread-1 | ApiProviderImpl | response: Webpay Transaction Bundle{ INPUT[CLIENTID=10000111;JVM_VERSION=1.7.0_21;TOKEN=72;]
INFO | 2016-06-09 04:37:29,542 |thread-2 | ApiProviderImpl | request: Webpay Transaction Bundle{ INPUT[CLIENTID=10000112;JVM_VERSION=1.7.0_21;TOKEN=20;] OUTPUT[]}
INFO | 2016-06-09 04:38:29,542 |thread-2 | ApiProviderImpl | request: Webpay Transaction Bundle{ INPUT[CLIENTID=10000112;JVM_VERSION=1.7.0_21;TOKEN=21;] OUTPUT[]}

You can see that the last two transactions have started but are not yet finished. Also I created a field called action which has the value of either request or response
Using this as search source you can run the search like this:

TOKEN=* request OR response 
| streamstats earliest(_time) AS earliest latest(_time) AS latest count(eval(if(action="request" OR action="response", 1, null()))) AS id by TOKEN 
| eval diff=latest-earliest 
| where id>1 | table id TOKEN action _time earliest latest 

and the result looks like this:

removed on request
As you can see the last two TOKEN will not show up in this search 😉

cheers, MuS

saradachelluboy
Explorer

Hi Mus,

I have tried

INFO TOKEN=* request OR response | stats latest(_time) AS latest earliest(_time) AS earliest by TOKEN | eval duration = latest - earliest | stats count by duration

I am getting data but that is incorrect 😞

Regards,
Sarada.

0 Karma

MuS
Legend

Well, I showed a way to do it. If the data in not correct it is pretty hard to help in this regard......
Why for example do you add another stats in the end and you wanted the session to be based on thread and TOKEN but you just use TOKEN.....

0 Karma
Get Updates on the Splunk Community!

Introducing the 2024 SplunkTrust!

Hello, Splunk Community! We are beyond thrilled to announce our newest group of SplunkTrust members!  The ...

Introducing the 2024 Splunk MVPs!

We are excited to announce the 2024 cohort of the Splunk MVP program. Splunk MVPs are passionate members of ...

Splunk Custom Visualizations App End of Life

The Splunk Custom Visualizations apps End of Life for SimpleXML will reach end of support on Dec 21, 2024, ...