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..
DEBUG 2015-05-13 15:31:40,590 fterReceiveRequest - Request Record : |33efb817-1948-4c8f-bdf4-4111aa1941cc | <GetDeliverySchedule xmlns="http://tempuri.org/"> <request> <DeliveryType /DotCom_Delivery">A</DeliveryType> <EndDate/DotCom_Delivery">2015-05-15</EndDate> <Region_StoreNo/DotCom_Delivery">970</Region_StoreNo> <Region_zip/DotCom_Delivery">11111</Region_zip> <StartDate/DotCom_Delivery">2015-05-13</StartDate> </request> </GetDeliverySchedule>
DEBUG 2015-05-13 15:31:41,276 BeforeSendReply - Response Record : |33efb817-1948-4c8f-bdf4-4111aa1941cc | <GetDeliveryScheduleResponse xmlns="http://tempuri.org/"> <GetDeliveryScheduleResult xmlns:a="http://schemas.datacontract.org/2004/07/DotCom_Delivery" xmlns:i="http://www.w3.org/2001/XMLSchema-instance"> <a:DeliveryCalendar> <a:Ranges> <a:DeliveryRange i:type="a:DeliveryDate"> <a:IsAvailableForDelivery>false</a:IsAvailableForDelivery> <a:Date>2015-05-13T00:00:00-04:00</a:Date> </a:DeliveryRange> <a:DeliveryRange i:type="a:DeliveryDate"> <a:IsAvailableForDelivery>false</a:IsAvailableForDelivery> <a:Date>2015-05-14T00:00:00-04:00</a:Date> </a:DeliveryRange> </a:Ranges> <a:TypeOfCalendar>DayType</a:TypeOfCalendar> <a:ZoneId>110</a:ZoneId> </a:DeliveryCalendar> <a:StatusCode>200</a:StatusCode> <a:StatusMessage>OK</a:StatusMessage> </GetDeliveryScheduleResult> </GetDeliveryScheduleResponse>
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
So... Request and Response are linked together correctly by the
transaction, but the duration field is zero instead of zero point something?
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
Looking at the events without
|transaction, does the timestamp to the left of the raw event appear correctly including subseconds?
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)