为什么我的IIS6请求在HTTPSYS_CACHEABLE阶段冻结了很长时间？

Question

我的一个应用程序在系统的某个特定部分经历了间歇性的延迟。用户会点击“保存”按钮，有时需要额外30秒的时间来响应。我打开ASP.NET追踪，然后使用Logman和ETW记录详细的跟踪。

痕迹显示，延迟发生在"HTTPSYS_CACHEABLE“阶段。但是，我不知道为什么这会造成延迟。我没有在IIS6中找到任何关于跟踪阶段的有用文档，谷歌也没有找到解决这个问题的其他人。

我试图通过更改注册表项和编辑HTTP.SYS来禁用machine.config缓存。任何操作都不会导致页面性能或跟踪日志发生任何更改。

跟踪结果的相关部分是本节。注意时间戳之间的差距。

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

我发现URL_CACHE_ACCESS_END跟踪条目发生在ASP.NET页面进程完成之前，HTTPSYS_CACHEABLE在完成之后发生。我发现了这一点，我在代码中添加了一个5秒钟的睡眠，然后比较了有睡眠和没有睡眠的跟踪。睡眠延迟出现在HTTPSYS_CACHEABLE时间戳中。

因此，这不是IIS或ASP.NET问题。在我的例子中，我们的一个开发人员更改了一些在某些情况下导致长循环运行的代码，我们的用户恰好触发了这些代码。