Por que minhas solicitações do IIS6 congelam por um longo tempo no estágio HTTPSYS_CACHEABLE?

Question

Um dos meus aplicativos estava enfrentando atrasos intermitentes em uma parte específica do sistema. Os usuários clicariam no botão "Salvar" e, às vezes, levaria 30 segundos a mais para responder. Ativei o rastreamento do ASP.NET e usei Logman e ETW para gravar vestígios.

O rastreamento mostrou que o atraso aconteceu no estágio "HTTPSYS_CACHEABLE". Mas não consegui descobrir por que isso estava causando um atraso. Não encontrei nenhuma documentação útil sobre os estágios de rastreamento no IIS6, e o Google não encontrou mais ninguém que tenha resolvido esse problema.

Eu tentei desativar o cache HTTP.SYS alterando uma chave de registro e editando o machine.config. Nenhuma ação causou qualquer alteração no desempenho da página ou nos logs de rastreamento.

A parte relevante dos resultados do rastreamento é esta seção. Observe a lacuna entre os 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

Descobri que a entrada de rastreio URL_CACHE_ACCESS_END ocorre antes de o processo de página do ASP.NET ser concluído e HTTPSYS_CACHEABLE acontece depois de concluído. Eu descobri isso adicionando um sono de 5 segundos no meu código e, em seguida, comparando os traços com e sem o sono. O atraso do sono aparece no registro de data e hora HTTPSYS_CACHEABLE.

Portanto, isso não é um problema do IIS ou do ASP.NET. No meu caso, um de nossos desenvolvedores alterou algum código que fazia com que um loop longo fosse executado em certos casos, que nossos usuários estavam acionando.