0

I have a OData REST API application running on IIS, using http.sys as the web server. I notice for around 5-10% of the requests my clients are noticing high latency (> 300 ms), but when I look at server side application logs, I see I processed the request in less than 50 ms. My clients are NOT geographically far from the web server. I think there is some non-network bottleneck, but I don't know where to look.

So far, I ran an Http.Sys ETW trace on the machine to capture a single request with high client reported latency. Here are the results:

Client Reported Latency: 323 ms
Server application reported processing time: 38 ms                           

Http.Sys trace:

1.RecvReq: 2023-08-14T22:33:39.653675000Z (“Request received”)

2.Parse:   2023-08-14T22:33:39.653723100Z (“Parsed request with URI …”)

3.Deliver: 2023-08-14T22:33:39.653755300Z (“Delivered request to server application from request queue IISPOOL_<AppName>”)

4.Deliver: 2023-08-14T22:33:39.653811300Z (“Delivered request to server application from request queue IISPOOL_<AppName>”)

5.RecvResp: 2023-08-14T22:33:39.697113000Z (“Server application passed response”) (EntityChunkCount: 23, HeaderLength: 329, StatusCode: 200)
                                                                                                                                                                                                                                            
6.RecvBody: 2023-08-14T22:33:39.701603000Z (“Server application passed entity body”)

7.FastRespLast: 2023-08-14T22:33:39.859224500Z (“Server Application passed the last response”)

8.FastSend: 2023-08-14T22:33:39.859284800Z (“Queued last response for sending. Status code is 200”)

I don't know fully how to interpret these logs, so I am not finding them helpful. (If you know where I can find resources to help interpret these logs, please share that).

Do these logs reveal anything insightful, like there is some bottleneck in my application logic, or maybe on the client side? What additional thing you would you suggest I look at next? I also checked performance counters on my machine (CPU/Memory) and it was low.

hpatel
  • 35
  • 6
  • it's queuing the response, so that might suggest a lot of traffic. – pcalkins Aug 30 '23 at 20:58
  • There is little load to my application when I collected this trace. There is less than 1 request per second (average). Do you have any further suggestion? – hpatel Aug 31 '23 at 14:36
  • 1
    I don't really think 300ms is all that bad... maybe look into optimizing the response and client... you might check how long that response is queued.... maybe check here if you think the queuing is the source of the lag: https://serverfault.com/questions/670721/cpu-at-50-yet-iis-asp-net-requests-still-being-queued – pcalkins Aug 31 '23 at 19:41
  • 1
    You can try using failed request tracking to get a detailed request process, which will include the time teken in each section. – samwu Sep 01 '23 at 09:12
  • @samwu can you provide a link to "failed request tracking" for more information? – hpatel Sep 01 '23 at 15:32
  • @pcalkins. From what I understand request queueing only happens before request is processed by server. I will check out your link to rule it out. Is it possible queueing happens after post processing for the response, and how can I check that? – hpatel Sep 01 '23 at 15:33
  • it's above my head really... but your trace suggests it's queuing the response, not the request. – pcalkins Sep 01 '23 at 15:56

0 Answers0