Mais um post de troubleshooting baseado em fatos reais.
Recentemente atuei na resolução de um problema “misterioso” em um ambiente de cliente.
Sintoma
Um usuário ao acessar o aplicativo web reportava que em determinados momentos o sistema não respondia (requisição web não retornava). Por exemplo, o browser envia uma requisição (POST) para o servidor web mas não recebe resposta, ficando a ampulheta durante um longo período de tempo sem completar com sucesso a execução.
Cenário
- Aplicativo web (ASP.NET WebForms) em apenas um servidor web com IIS7 e .NET Framework 4.0;
- Aplicativo web acessa banco de dados SQL Server 2012 em outro servidor;
- Aplicativo web acessa outros serviços de negócio em servidores diferentes na intranet via TCP e via HTTP;
- Nenhum log de problema foi encontrado no Event Viewer ou do aplicativo web (instrumentação).
Investigação
A seguir detalho alguns procedimentos realizados para isolar, entender e corrigir o problema.
Passo 1 – descartar problemas de rede
Com as ferramentas de desenvolvimento do browser (F12) identificamos que as requisições eram enviadas e ficavam aguardando resposta por um longo período. Ao acessar o mesmo sistema em outra janela anônima quase ao mesmo tempo, tudo funcionava.
A suspeita de problema de conectividade foi deixada de lado, pelo menos até novos indícios.
Passo 2 – garantir que a requisição misteriosa está chegando no servidor web
O primeiro foco é descartar totalmente o problema de conexão do cliente e garantir que o servidor web recebeu a requisição que não responde e então identificar o que está acontecendo com ela dentro do servidor.
Com o recurso de “Request Monitor” do IIS7 foi possível detectar que determinadas requisições estavam com um tempo de execução bastante alto (“Tempo Decorrido”), ou seja, a requisição chegou para o IIS e não retornou para o cliente pois ainda estava sendo processada.
Passo 3 – Verificando o consumo de recursos do IIS
Como há uma requisição em execução por um longo período a investigação passou a ser sobre a lógica de negócio, a qual poderia estar fazendo algum processamento pesado e demorado. Desta forma, é possível utilizar o próprio gerenciador de tarefas para verificar o consumo de recursos como memória, CPU, rede, etc. (obs: como alternativa poderia ser utilizado o perfmon.exe e os contadores de performance)
Conforme a imagem anterior, o consumo de recursos está bastante baixo então até novos indícios descarta-se qualquer lógica pesada de processamento do aplicativo.
Passo 4 – Verificando locks
Como o consumo de CPU apresentou ser pífio, a desconfiança passa para algum lock de recurso ou dependência de serviços externos acionados pela requisição.
Por exemplo, a requisição poderia acionar alguma lógica de negócio que por sua vez acessa o banco de dados que pode estar sobrecarregado e demorando para responder ou em lock. Outro exemplo de possibilidade é o consumo de algum serviços externo durante o processamento da requisição, por exemplo, algum web service de terceiros.
Como poderia ter muitos cenários diferentes para analisar, uma forma de ir direto ao ponto é tirar um dump (fotografia) do processo do servidor web (w3wp.exe) e ver o que ele anda fazendo.
Passo 5 – Analisar o dump
Para analisar o dump uso o ntsd.exe, ajusto os símbolos e carrego as bibliotecas de análise de código gerenciado. Estes três passos explico em mais detalhes em outro artigo: “Identificando a causa de um alto e crescente consumo de memória em produção” – item Passo 3.
Neste momento o interesse está em obter informações sobre a pilha de execução (stack trace) do processo (w3wp.exe), ou seja, o que cada thread está fazendo.
Para obter esta informação utilizo o comando !EEStack -short, que lista a stack trace de todas as threads do processo (referência).
Uma das threads listadas parece bastante suspeita, pois contém rastro de execução de uma requisição web do ASP.NET e poderia ser a requisição demorada.
Olhando em mais detalhes esta stacktrace é possível identificar que ela aciona uma rotina de negócio do aplicativo (método ValidateUser) que por sua vez faz alguma comunicação via Socket. Ou seja, acessou algum serviço externo via TCP e está aguardando uma resposta.
Isto se encaixa com o cenário até aqui investigado.
A suspeita de que a requisição está aguardando algo está se comprovando válida, falta descobrir qual é o serviço externo acessado e porque está demorando em responder.
A thread 57 é a que contém o possível problema, então alterno o contexto para investigar apenas ela. Para isto, uso o comando ~57s.
Sabendo que o problema está em uma comunicação com Socket, investigo os objetos do tipo Socket que estão em memória.
Estes objetos poderão dizer algo sobre onde está o serviço remoto que está causando o problema.
No caso encontrou apenas um objeto, então agora obtêm-se mais detalhes sobre este objeto.
O objeto possui um campo do tipo EndPoint que pode dizer com quem está se comunicando.
Investigo o campo EndPoint para obter mais informações.
O EndPoint possui um campo do tipo IPAddress e o número da porta de comunicação, no caso da porta já é possível saber o valor: 5337.
Para obter o IP é necessário obter mais informações sobre o objeto IPAddress.
Obtenho mais informações através do m_ToString e então consigo ver o IP do serviço externo.
Conclusão
Desfeito o mistério foi necessário explicar para a equipe do aplicativo o que estava acontecendo e tratar o motivo do serviço externo não estar respondendo em alguns momentos. Além disso, recomendar ajustes no aplicativo web para melhor se comportar com esse cenário sem impactar em outras requisições do aplicativo web.
Segundo dados coletados pelo Dump foi possível identificar que: o método ValidateUser do MembershipProvider customizado pelo aplicativo está acessando um serviço externo no IP 192.168.104.11 e porta 5337 e este serviço não responde adequadamente.
Neste cenário caso não utilizássemos o recurso de dump poderíamos gastar minutos preciosos em suposições de cenários de problema.
O dump permitiu atuar de forma rápida e direta no problema em questão, sem perda de tempo.
Fonte: Clique aqui