Estudo de caso: ASP clássico - problemas mais comuns - Parte 01.

Estive há algum tempo em um cliente que reclamava de algum processo que estava causando o uso de 100% de CPU no seu servidor SQL. Como efeito disso, uma importante aplicação Web sofria lentidão generalizada. O servidor em questão era uma máquina bem robusta, e que atendia exclusivamente a essa aplicação Web baseada no ASP clássico.

Para começar e antes de tudo, acho que vale fazer uma distinção importante aqui:

Causa: do Lat. Causa, s. f., aquilo ou aquele que ocasiona um acontecimento ou faz que uma coisa exista; princípio; origem; motivo, razão, pretexto; partido.

Efeito: do Lat. Effectu, s. m., resultado, consequência; produto de uma causa; fim; destino; aplicação; eficácia; execução, realização; cumprimento; impressão moral, sensação; Fís., fenomeno de particular importância produzido por uma causa bem determinada.

A nossa experiência no suporte Microsoft tem nos mostrado que confundir causa e efeito é algo muito comum. Eu pessoalmente sou muito cético quando se atribui a causa ao SQL Server ou ao IIS quando há problemas em um ambiente Web. Isso porque, em geral, tanto SQL quanto o IIS sofrem os efeitos de aplicações mal comportadas. Se uma aplicação faz uso incorreto de memória ou de outros recursos do sistema, em geral, os efeitos aparecem no IIS. Se a aplicação faz uso de queries de forma inadvertida ou tem um modelo de dados inadequado, em geral, os efeitos aparecem no SQL.

Com base nessa experiência iniciei o meu trabalho atacando exatamente a minha área de atuação, ou seja, a configuração do servidor IIS. O servidor em questão era baseado no Windows 2003 SP1 com IIS6.

Como sempre, o primeiro passo foi olhar os contadores de performance para avaliar se o equipamento estava bem dimensionado e se havia algum gargalo. Os contadores básicos do S.O. são aqueles relacionados a CPU, disco, rede e memória. Infelizmente (ou felizmente) já de início foi possível descartar a existência de gargalos; a máquina estafa “sobrando”. Porém algo que as vezes passa desapercebido me chamou a atenção: o consumo de memória de um Worker Process do IIS6.... mas vamos guardar essa informação para logo mais.

Também olhei o log de eventos de aplicação. Por incrível que pareça é possível contar nos dedos os administradores que realmente olham e dão importância aos logs do sistema. E ai cabe um puxão de orelha: isso quase sempre só acontece com administradores Windows. Se pegaramos os administradores Unix facilmente encontraremos um que regularmente dá uma “olhadela” no syslog.

Pois bem, no log de aplicações encontrei algo semelhante ao descrito abaixo:

8/20/2007 4:49:39 PM Active Server Pages Warning None 9 N/A SERVER_01 Warning: 500 Server Error. .
8/20/2007 4:49:25 PM Active Server Pages Warning None 9 N/A SERVER_01 Warning: File /search_payment.asp Line 29 Type mismatch: 'fValidateC'. .
8/20/2007 4:48:58 PM Active Server Pages Warning None 9 N/A SERVER_01 Warning: File /basket_001.asp Line 33 Type mismatch: 'oBasket.Item(...)'. .
8/20/2007 4:48:48 PM Active Server Pages Warning None 9 N/A SERVER_01 Warning: File /finalizebuy01_.asp Line 304 Type mismatch: 'oBasket.Item(...)'. .

Obviamente, por essas entradas, fica claro que a aplicação estava apresentando problemas. Havia pelo menos três tipos distintos de erros, e nesse instante não havia mais como descartar que o SQL poderia estar sofrendo efeitos de uma aplicação mal comportada. Ainda assim não havia nenhuma relação comprovada entre esses erros e o consumo de 100% CPU no banco de dados.

A primeira coisa que me ocorreria é tentar capturar mais informações no instante em que esses erros estavam ocorrendo, ou no instante que a CPU no banco estivesse em 100%. Seria possível capturar facilmente esses erros gerando um dump de memória utilizando o utilitário Debug Diagnostics, também conhecido como DebugDiag (que pode ser baixado do www.microsoft.com/downloads).

Entretando isso simplesmente não era possível nesse caso. O porquê? Dois fatores contribuiram para tornar isso impossível:

a) a aplicação era crítica para o cliente (uma solução de comércio eletrônico);
b) o consumo de memória do Worker Process responsável por processar a aplicação;

Como citei há pouco, não havia gargalos no ambiente. De fato, o uso de memória física estava muito baixo. Mas então qual era o problema com o Worker Process? O problema estava exatamente no consumo de memória virtual ou melhor, do espaço de endereços de memória virtual. Usando o contador Process\Virtual Bytes do performance monitor notei que a instância do W3WP.EXE que executava a aplicação ocupada 1.8Gb de memória virtual!! Isso realmente é algo MUITO além do normal (em geral uma aplicação “bem comportada” costuma consumir menos que 1Gb de memória virtual).

E qual o problema de usar o Debug Diagnostics? Ao se gerar um dump de memória, o DebugDiag (e qquer outro debugger) irá criar um arquivo cujo tamanho final será muito próximo ao tamanho de memória virtual utilizada pelo processo (no nosso caso, 1.8Gb). Infelizmente, gerar um arquivo desse tamanho pode ser uma tarefa bem demorada, mesmo em um equipamento adequado.

Apesar de não poder gerar o dump de memória, esse consumo excessivo de memória também me apontou para algumas possibilidades interessantes em relação a causa do problema. Infelizmente a ausência do dump também me deixava somente no terreno das possibilidades (ou das incertezas) e uma outra abordagem se fazia necessária. Como identificar a origem dos problemas da aplicação? Como encontrar uma correlação entre os problemas na aplicação e os efeitos no banco de dados?

A única solução possível foi fazer uma revisão estática de código (popularmente chamado "Code Review"). Antes que alguém pergunte, fazer isso numa aplicação que tem 1000 páginas é inviável. E esse era o caso. Todavia, sabemos que "estatisticamente" o código costuma apresentar um padrão de desenvolvimento, ou seja, se há algo errado, o erro costuma ser repetido em diversos locais do código. Também sabemos que a regra 80/20 costuma se aplicar, ou seja, em 20% das páginas estão concentrados 80% dos problemas mais críticos da aplicação. Por isso o nosso objetivo em um Code Review (executado com uma visão de Suporte) é atacar extamente esses 20% de código.

O primeiro passo então é definir o nosso escopo (os 20%), e isso é feito através da análise de logs do IIS. Através do uso do LogParser, conseguimos identificar as TOP páginas com Erros 500, e também as páginas com maior tempo de duração. O Code Review é realizado com foco nessas páginas. Como fazer isso?

# maior número de hits
logparser "SELECT TOP 20 cs-uri-stem as URI, count(*) as Hits, AVG(time-taken) as AvgTimeTaken, AVG(sc-bytes) As AvgSentBytes, AVG(cs-bytes) as AvgRecvBytes FROM ex*.log ORDER BY Hits DESC GROUP BY cs-uri-stem"
#maior tempo gasto
logparser "SELECT TOP 20 cs-uri-stem as URI, count(*) as Hits, AVG(time-taken) as AvgTimeTaken, AVG(sc-bytes) As AvgSentBytes, AVG(cs-bytes) as AvgRecvBytes FROM ex*.log ORDER BY AvgTimeTaken DESC GROUP BY cs-uri-stem"
# páginas com erros 500, ordenadas pelo número de hits
logparser "SELECT TOP 20 cs-uri-stem as URI, count(*) as Hits, AVG(time-taken) as AvgTimeTaken, AVG(sc-bytes) As AvgSentBytes, AVG(cs-bytes) as AvgRecvBytes FROM ex*.log WHERE sc-status = 500 ORDER BY Hits DESC GROUP BY cs-uri-stem"

Com essas queries do logparser conseguimos identificar o nosso conjunto de páginas. Após isso, basta fazer uso de um pouco de experiência (e algumas referências que listo abaixo) para varrer o código e encontrar (se houver) os principais problemas da aplicação. Para resumir o resultado do trabalho, após a análise do código das páginas, o que foi encontrado foi o seguinte:

• Diversos problemas em relação ao mecanismo de acesso à dados utilizado, causados pela falta de padronização no acesso ao banco de dados. Estavam sendo usadas queries “ad-hoc”, stored procedures, updatable client-side cursors e instruções SQL DML na atualização dos dados, algumas vezes diretamente a partir do código ASP e outras vezes com o auxilio de um componente COM, ou seja, uma tríade de mecanismos para acesso à dados.
• O sistema armazenava um non-agile object em uma variável de sessão para um dos processos mais importanes do site (a cesta de compras).
• O cache estava desabilitado programaticamente em praticamente 80% do código da aplicação (o que revela também uma falta de padronização ao se desenvolver o código - afinal, se houvesse padrão ou seria tudo, ou nada habilitado).
• A forma com que o código foi criado e estava organizado gerava grandes asp templates para serem processados pelo IIS (e isso representa uma sobrecarga a mais no servidor).  

Como podemos ver havia grandes problemas a serem enfretados, e um longo trabalho teve início a partir desta análise da aplicação. Se você leu estes últimos itens acima e ficou pensando consigo mesmo: "Puxa, e agora? Não entendi nem por que isso é considerado problema!", não se preocupe. Nos próximos posts eu vou comentar cada um dos tópicos encontrados. Por outro lado se você entendeu tudo, mesmo assim eu lhe convido a retornar, afinal, sempre pode haver alguma informação que contribua para o seu conhecimento.

Vejo vocês em breve.

Paulo.