Why do my IIS6 requests freeze for a long time in the HTTPSYS_CACHEABLE stage?

Question

One of my applications was experiencing intermittent delays in a specific part of the system. Users would click the "Save" button, and sometimes it would take an extra 30 seconds to respond. I turned on ASP.NET tracing and then used Logman and ETW to record detailed traces.

The trace showed that the delay happened in the "HTTPSYS_CACHEABLE" stage. But, I could not figure out why that was causing a delay. I didn't find any useful documentation about the trace stages in IIS6, and Google didn't find anyone else who had solved this problem.

I tried to disable HTTP.SYS caching by changing a registry key and by editing machine.config. Neither action caused any change in the page performance or the trace logs.

The relevant part of the trace results is this section. Note the gap between the timestamps.

IISCache: URL_CACHE_ACCESS_END - IIS ends accessing URL cache
  ErrorCode: 0x00000000
  PhysicalPath: H:\JobTraQ_Site\
  URLInfoFromCache: 1
  URLInfoAddedToCache: 0
  ContextIDSeq: 4
  Timestamp: 00:30:29.406.250000

IISCache: HTTPSYS_CACHEABLE - IIS decides if the request is HTTP.SYS cacheable
  Reason: RESPONSE_MORE_DATA
  HttpsysCacheable: 0
  ContextIDSeq: 4
  Timestamp: 00:30:53.421.875000

Answer 1

I discovered that the URL_CACHE_ACCESS_END trace entry happens before the ASP.NET page process is complete, and HTTPSYS_CACHEABLE happens after it's complete. I discovered this by adding a 5-second sleep into my code and then comparing the traces with and without the sleep. The sleep's delay appears in the HTTPSYS_CACHEABLE timestamp.

So, this is not an IIS or ASP.NET problem. In my case, one of our developers changed some code that caused a long loop to run in certain cases, which our users just happened to be triggering.