topic Re: Transaction to Find Duration in Splunk Search

Transaction to Find Duration

skoelpin — Wed, 13 May 2015 19:48:57 GMT

I have a simple web service with a request and response called DeliverySchedule. The request and response have a unique identifier called a GUID which are in pairs. I'm trying to find the duration (response time) between the response and request.

Here's my search which is returning some correct durations but also listing 0 for more than 400 events . I'm also missing a lot of events

index=unleashed  "deliveryschedule"   | transaction GUID startswith="Request" endswith="Reply" | timechart avg(duration)

GUID = "33efb817-1948-4c8f-bdf4-4111aa1941cc" in this case. We will only have 2 matching GUID's which are attached to the req/resp. They will be different for each req/resp. I also did a field extraction called 'GUID' to capture the GUID between the pipes..

REQUEST

DEBUG 2015-05-13 15:31:40,590
 fterReceiveRequest - Request Record : |33efb817-1948-4c8f-bdf4-4111aa1941cc |
 &lt;GetDeliverySchedule xmlns="http://tempuri.org/"&gt;
  &lt;request&gt;
    &lt;DeliveryType /DotCom_Delivery"&gt;A&lt;/DeliveryType&gt;
    &lt;EndDate/DotCom_Delivery"&gt;2015-05-15&lt;/EndDate&gt;
    &lt;Region_StoreNo/DotCom_Delivery"&gt;970&lt;/Region_StoreNo&gt;
    &lt;Region_zip/DotCom_Delivery"&gt;11111&lt;/Region_zip&gt;
    &lt;StartDate/DotCom_Delivery"&gt;2015-05-13&lt;/StartDate&gt;
  &lt;/request&gt;
&lt;/GetDeliverySchedule&gt;

RESPONSE

DEBUG 2015-05-13 15:31:41,276        BeforeSendReply    - Response Record : |33efb817-1948-4c8f-bdf4-4111aa1941cc |
 &lt;GetDeliveryScheduleResponse xmlns="http://tempuri.org/"&gt;
  &lt;GetDeliveryScheduleResult xmlns:a="http://schemas.datacontract.org/2004/07/DotCom_Delivery" xmlns:i="http://www.w3.org/2001/XMLSchema-instance"&gt;
    &lt;a:DeliveryCalendar&gt;
      &lt;a:Ranges&gt;
        &lt;a:DeliveryRange i:type="a:DeliveryDate"&gt;
          &lt;a:IsAvailableForDelivery&gt;false&lt;/a:IsAvailableForDelivery&gt;
          &lt;a:Date&gt;2015-05-13T00:00:00-04:00&lt;/a:Date&gt;
        &lt;/a:DeliveryRange&gt;
        &lt;a:DeliveryRange i:type="a:DeliveryDate"&gt;
          &lt;a:IsAvailableForDelivery&gt;false&lt;/a:IsAvailableForDelivery&gt;
          &lt;a:Date&gt;2015-05-14T00:00:00-04:00&lt;/a:Date&gt;
        &lt;/a:DeliveryRange&gt;
&lt;/a:Ranges&gt;
      &lt;a:TypeOfCalendar&gt;DayType&lt;/a:TypeOfCalendar&gt;
      &lt;a:ZoneId&gt;110&lt;/a:ZoneId&gt;
    &lt;/a:DeliveryCalendar&gt;
    &lt;a:StatusCode&gt;200&lt;/a:StatusCode&gt;
    &lt;a:StatusMessage&gt;OK&lt;/a:StatusMessage&gt;
  &lt;/GetDeliveryScheduleResult&gt;
&lt;/GetDeliveryScheduleResponse&gt;

Re: Transaction to Find Duration

martin_mueller — Wed, 13 May 2015 20:47:53 GMT

Shouldn't it be endswith="Response"?

Re: Transaction to Find Duration

skoelpin — Wed, 13 May 2015 20:55:31 GMT

Thanks for the response. I tried a lot of different strings for startswith="" and endswith="" with no luck.

The one I'm currently trying is startswith="fterReceiveRequest" endswith="BeforeSendReply"and still returning 400+ values with duration = 0..

It's working correctly for some events but for 400+ of them, its returning duration=0. I even went to some of the events which have duration=0 and took the difference between the response and request and it's typically in the 200-300ms range, no events have duration = 0 from what I've seen.

The example I posted above is an event which has duration = 0

Re: Transaction to Find Duration

martin_mueller — Wed, 13 May 2015 20:57:34 GMT

So... Request and Response are linked together correctly by the transaction, but the duration field is zero instead of zero point something?

Re: Transaction to Find Duration

skoelpin — Wed, 13 May 2015 21:27:28 GMT

Yes correct. Transaction is working as expected by grouping the request and response into the same event which have a matching guid. The duration for most is absolute 0. For the on one's that return a valid duration, they are equal to like 0.336 and 0.386.. we rarely have response times over a second. After i fix this issue ill change it from seconds to ms

Re: Transaction to Find Duration

martin_mueller — Wed, 13 May 2015 21:29:02 GMT

Both _time fields are extracted correctly?

Re: Transaction to Find Duration

skoelpin — Wed, 13 May 2015 21:33:16 GMT

Not sure. Can you elaborate on that?

Re: Transaction to Find Duration

martin_mueller — Wed, 13 May 2015 21:35:23 GMT

Looking at the events without |transaction, does the timestamp to the left of the raw event appear correctly including subseconds?

Re: Transaction to Find Duration

skoelpin — Wed, 13 May 2015 22:23:29 GMT

Yes it does. All the timestamps are correct

Re: Transaction to Find Duration

woodcock — Thu, 14 May 2015 00:03:46 GMT

Transaction does a ton of things that you don't appear to need. Have you tried something like this:

index=unleashed  "deliveryschedule"  | stats earliest(_time) AS firstTime latest(_time) AS lastTime by GUID | eval duration=lastTime-firstTime | timechart avg(duration)

Re: Transaction to Find Duration

skoelpin — Thu, 14 May 2015 13:58:13 GMT

I used your suggestion and pasted a snippet of the results below. Notice the difference between the first and last time, why do some have the same times? I looked at some of the events that had 0.000 for the duration and there was a noticeable difference in time.

Here's a request and response pair of timestamp from looking at the events from GUID 023b0868-8fff-4f52-8374-61a305f96ef4

Request = 2015-05-14 02:27:33,405 80361983ms

Response = 2015-05-14 02:27:33,810 80362388ms

RTG_GUID                                     firstTime       lastTime        duration
| 021c4152-e86a-42d5-ad30-b0ace69ea807 |    1431597859.119  1431597860.070  0.951
| 023b0868-8fff-4f52-8374-61a305f96ef4 |    1431584853.405  1431584853.405  0.000
| 027e273f-3e7b-423e-833f-5062ddeafcae |    1431604857.327  1431604857.327  0.000
| 05ba2e35-0275-457a-93c6-cca482bc7c63 |    1431610171.550  1431610171.550  0.000
| 06f6b992-c42c-4409-9dd2-09ea62c99ebe |    1431581886.482  1431581886.841  0.359
| 0a3046db-42fb-4fdc-9845-374a9765b540 |    1431603377.069  1431603377.069  0.000
| 0a48e95c-6a4d-4b45-9334-6698d87f8d9e |    1431580396.203  1431580396.203  0.000
| 0a972800-4681-44e9-805c-915d5b5deeb0 |    1431590652.840  1431590653.339  0.499
| 0c279929-c087-4fce-a685-7a129af473fe |    1431591504.562  1431591504.562  0.000
| 1084be43-ec11-42fa-a240-0605c7921126 |    1431582171.221  1431582171.564  0.343

Re: Transaction to Find Duration

martin_mueller — Thu, 14 May 2015 14:38:07 GMT

Include a count in the stats to see if both Request and Response are actually counted. If you get a count of 1, see if the GUID has been extracted correctly. If you get a count of 2, re-check those extracted timestamps.

Re: Transaction to Find Duration

woodcock — Thu, 14 May 2015 14:59:49 GMT

I suspect that your timestamping may not be working as you are expecting it to. In other words, the timestamp inside your event is not actually the timetamp that Splunk has given to the event. Try this search and see if the _time value matches what you see in each event (I expect that it won't):

... | table _raw _time

Re: Transaction to Find Duration

skoelpin — Thu, 14 May 2015 15:07:50 GMT

I just added a count after stats and count = 1 for all duration=0.

And count = 2 for all durations that equal the real difference in timestamps. So this has to be an issue with my timestamp then?

Re: Transaction to Find Duration

martin_mueller — Thu, 14 May 2015 15:12:54 GMT

count=1 suggests only one event was found for that GUID, so the duration must be zero.

Make sure both events are in the searched time range, and that both events have the correct GUID value extracted - including case and possible spaces at both ends.

Re: Transaction to Find Duration

martin_mueller — Thu, 14 May 2015 15:13:27 GMT

Note: This would affect all methods of calculating the duration, whether based on transaction, stats, or anything else.

Re: Transaction to Find Duration

skoelpin — Thu, 14 May 2015 15:36:06 GMT

I just looked up a GUID in the event which was coming back as duration=0 and it's in 2 events both happened today within a half second of each other.

I compared a GUID which has duration=0 to a GUID which has a valid duration.

Correct Duration
This has the request and response in separate events

Duration = 0
This has the request and response in the same event

Do I have to modify my props.conf file so the line breaks for the response so I have separate events for the request and response?

Re: Transaction to Find Duration

martin_mueller — Thu, 14 May 2015 15:39:02 GMT

That certainly sounds like an event breaking issue. Do post the props.conf settings for that sourcetype along with a longer sample of the source file before splunking it (pastebin.com?).

Re: Transaction to Find Duration

woodcock — Thu, 14 May 2015 15:42:08 GMT

Yes, this is definitely a problem that you need to fix if you are going to anything like what we have been discussing.

Re: Transaction to Find Duration

skoelpin — Mon, 28 Sep 2020 19:57:54 GMT

Why would some of the events have the request and response in the same event while others have ONLY a request or response in the event?

Do you have any suggestions as to how I should configure my regex for LINE_BREAKER so only 1 request or response is present for each event?

Here's what I currently have in my props.conf file.
[Unleashed_Message_Log]
LINE_BREAKER = |([\r\n]+)

There's a backslash before the first pipe, before r and before n. It looks like answers.splunk didnt include it in my response when I submitted it