- \n
- Aplicativo web (ASP.NET WebForms) em apenas um servidor web com IIS7 e .NET Framework 4.0;<\/li>\n
- Aplicativo web acessa banco de dados SQL Server 2012 em outro servidor;<\/li>\n
- Aplicativo web acessa outros servi\u00e7os de neg\u00f3cio em servidores diferentes na intranet via TCP e via HTTP;<\/li>\n
- Nenhum log de problema foi encontrado no Event Viewer ou do aplicativo web (instrumenta\u00e7\u00e3o).<\/li>\n<\/ul>\n
Investiga\u00e7\u00e3o<\/h1>\n
A seguir detalho alguns procedimentos realizados para isolar, entender e corrigir o problema.<\/p>\n
Passo 1 \u2013 descartar problemas de rede<\/h3>\n
Com as ferramentas de desenvolvimento do browser (F12) identificamos que as requisi\u00e7\u00f5es eram enviadas e ficavam aguardando resposta por um longo per\u00edodo. Ao acessar o mesmo sistema em outra janela an\u00f4nima quase ao mesmo tempo, tudo funcionava.<\/p>\n
![\"\"](\"http:\/\/gianfratti.com\/wp-content\/uploads\/2017\/08\/6GNw72C.png\" "\\"Browser\\"")
<\/a>A suspeita de problema de conectividade foi deixada de lado, pelo menos at\u00e9 novos ind\u00edcios.<\/p>\nPasso 2 \u2013 garantir que a requisi\u00e7\u00e3o misteriosa est\u00e1 chegando no servidor web<\/h3>\n
O primeiro foco \u00e9 descartar totalmente o problema de conex\u00e3o do cliente e garantir que o servidor web recebeu a requisi\u00e7\u00e3o que n\u00e3o responde e ent\u00e3o identificar o que est\u00e1 acontecendo com ela dentro do servidor.<\/p>\n
Com o recurso de \u201cRequest Monitor<\/a>\u201d do IIS7 foi poss\u00edvel detectar que determinadas requisi\u00e7\u00f5es estavam com um tempo de execu\u00e7\u00e3o bastante alto (\u201cTempo Decorrido\u201d), ou seja, a requisi\u00e7\u00e3o chegou para o IIS e n\u00e3o retornou para o cliente pois ainda estava sendo processada.<\/p>\n
![\"\"](\"http:\/\/gianfratti.com\/wp-content\/uploads\/2017\/08\/eWA30HN.png\" "\\"Request")
<\/a><\/p>\nPasso 3 \u2013 Verificando o consumo de recursos do IIS<\/h3>\n
Como h\u00e1 uma requisi\u00e7\u00e3o em execu\u00e7\u00e3o por um longo per\u00edodo a investiga\u00e7\u00e3o passou a ser sobre a l\u00f3gica de neg\u00f3cio, a qual poderia estar fazendo algum processamento pesado e demorado. Desta forma, \u00e9 poss\u00edvel utilizar o pr\u00f3prio gerenciador de tarefas para verificar o consumo de recursos como mem\u00f3ria, CPU, rede, etc. (obs: como alternativa poderia ser utilizado o perfmon.exe e os contadores de performance<\/em>)<\/p>\n
![\"\"](\"http:\/\/gianfratti.com\/wp-content\/uploads\/2017\/08\/wBCI2bw.png\" "\\"Gerenciador")
<\/a><\/p>\nConforme a imagem anterior, o consumo de recursos est\u00e1 bastante baixo ent\u00e3o at\u00e9 novos ind\u00edcios descarta-se qualquer l\u00f3gica pesada de processamento do aplicativo.<\/p>\n
Passo 4 \u2013 Verificando locks<\/h3>\n
Como o consumo de CPU apresentou ser p\u00edfio, a desconfian\u00e7a passa para algum lock de recurso ou depend\u00eancia de servi\u00e7os externos acionados pela requisi\u00e7\u00e3o.
\nPor exemplo, a requisi\u00e7\u00e3o poderia acionar alguma l\u00f3gica de neg\u00f3cio que por sua vez acessa o banco de dados que pode estar sobrecarregado e demorando para responder ou em lock. Outro exemplo de possibilidade \u00e9 o consumo de algum servi\u00e7os externo durante o processamento da requisi\u00e7\u00e3o, por exemplo, algum web service de terceiros.<\/p>\nComo poderia ter muitos cen\u00e1rios diferentes para analisar, uma forma de ir direto ao ponto \u00e9 tirar um dump (fotografia) do processo do servidor web (w3wp.exe) e ver o que ele anda fazendo.<\/p>\n
![\"\"](\"http:\/\/gianfratti.com\/wp-content\/uploads\/2017\/08\/afAxoai.png\" "\\"Tirando")
<\/a><\/p>\nPasso 5 \u2013 Analisar o dump<\/h3>\n
Para analisar o dump uso o ntsd.exe, ajusto os s\u00edmbolos e carrego as bibliotecas de an\u00e1lise de c\u00f3digo gerenciado. Estes tr\u00eas passos explico em mais detalhes em outro artigo: \u201cIdentificando a causa de um alto e crescente consumo de mem\u00f3ria em produ\u00e7\u00e3o<\/a>\u201d \u2013 item Passo 3.<\/p>\n
Neste momento o interesse est\u00e1 em obter informa\u00e7\u00f5es sobre a pilha de execu\u00e7\u00e3o (stack trace) do processo (w3wp.exe), ou seja, o que cada thread est\u00e1 fazendo.
\nPara obter esta informa\u00e7\u00e3o utilizo o comando !EEStack -short, que lista a stack trace de todas as threads do processo (refer\u00eancia<\/a>).<\/p>\n![\"\"](\"http:\/\/gianfratti.com\/wp-content\/uploads\/2017\/08\/QYXhyiv.png\" "\\"EESTack\\"")
<\/a><\/p>\nUma das threads listadas parece bastante suspeita, pois cont\u00e9m rastro de execu\u00e7\u00e3o de uma requisi\u00e7\u00e3o web do ASP.NET e poderia ser a requisi\u00e7\u00e3o demorada.<\/p>\n
![\"\"](\"http:\/\/gianfratti.com\/wp-content\/uploads\/2017\/08\/R41Lra1.png\" "\\"Thread")
<\/a><\/p>\nOlhando em mais detalhes esta stacktrace \u00e9 poss\u00edvel identificar que ela aciona uma rotina de neg\u00f3cio do aplicativo (m\u00e9todo ValidateUser) que por sua vez faz alguma comunica\u00e7\u00e3o via Socket. Ou seja, acessou algum servi\u00e7o externo via TCP e est\u00e1 aguardando uma resposta.<\/p>\n
Isto se encaixa com o cen\u00e1rio at\u00e9 aqui investigado.<\/p>\n
![\"\"](\"http:\/\/gianfratti.com\/wp-content\/uploads\/2017\/08\/l4OIz0l.png\" "\\"Socket.Receive\\"")
<\/a><\/p>\nA suspeita de que a requisi\u00e7\u00e3o est\u00e1 aguardando algo est\u00e1 se comprovando v\u00e1lida, falta descobrir qual \u00e9 o servi\u00e7o externo acessado e porque est\u00e1 demorando em responder.<\/p>\n
A thread 57 \u00e9 a que cont\u00e9m o poss\u00edvel problema, ent\u00e3o alterno o contexto para investigar apenas ela. Para isto, uso o comando ~57s.<\/p>\n
![\"\"](\"http:\/\/gianfratti.com\/wp-content\/uploads\/2017\/08\/2dc9LR2.png\" "\\"Investigando")
<\/a><\/p>\nSabendo que o problema est\u00e1 em uma comunica\u00e7\u00e3o com Socket, investigo os objetos do tipo Socket que est\u00e3o em mem\u00f3ria.
\nEstes objetos poder\u00e3o dizer algo sobre onde est\u00e1 o servi\u00e7o remoto que est\u00e1 causando o problema.<\/p>\n![\"\"](\"http:\/\/gianfratti.com\/wp-content\/uploads\/2017\/08\/4YYKT8u.png\" "\\"Investigando")
<\/a><\/p>\nNo caso encontrou apenas um objeto, ent\u00e3o agora obt\u00eam-se mais detalhes sobre este objeto.
\nO objeto possui um campo do tipo EndPoint que pode dizer com quem est\u00e1 se comunicando.<\/p>\n![\"\"](\"http:\/\/gianfratti.com\/wp-content\/uploads\/2017\/08\/AXaRjVw.png\" "\\"Informa\u00e7\u00f5es")
<\/a><\/p>\nInvestigo o campo EndPoint para obter mais informa\u00e7\u00f5es.<\/p>\n
![\"\"](\"http:\/\/gianfratti.com\/wp-content\/uploads\/2017\/08\/ckXJKeC.png\" "\\"Investigando")
<\/a><\/p>\nO EndPoint possui um campo do tipo IPAddress e o n\u00famero da porta de comunica\u00e7\u00e3o, no caso da porta j\u00e1 \u00e9 poss\u00edvel saber o valor: 5337.
\nPara obter o IP \u00e9 necess\u00e1rio obter mais informa\u00e7\u00f5es sobre o objeto IPAddress.<\/p>\n![\"\"](\"http:\/\/gianfratti.com\/wp-content\/uploads\/2017\/08\/6uKibKl.png\" "\\"Investigando")
<\/a><\/p>\nObtenho mais informa\u00e7\u00f5es atrav\u00e9s do m_ToString e ent\u00e3o consigo ver o IP do servi\u00e7o externo.<\/p>\n