Há pouco tempo escrevi um artigo sobre as exceções no .NET e seu impacto na performance. Nele trago uma introdução sobre o SEH e explico a correlação entre o fluxo de lançamento de exceções com a degradação no desempenho da aplicação.
O artigo ficou muito interessante pois nele fizemos uma prova de conceito com um teste de carga comparando o comportamento em um cenário com alto volume de lançamentos de exceções com um cenário onde evitamos as exceções.
Leia mais em: Impacto dos Handlers de Exceptions na performance das aplicações .net core
Conhecer os impactos na performance é muito importante, mas tão importante quando isso é conhecer as ferramentas e técnicas necessárias para conseguir identificar e resolver essas exceções!
Vou focar em técnicas nas quais não utilizarei arquivos de logs nem nenhum tipo de instrumentação.
O objetivo deste artigo é introduzir algumas ferramentas poderosas de troubleshooting de exceções no .NET.
Contadores de Performance
Antes de sair se aprofundando na análise, precisamos identificar se a nossa aplicação está lançando um alto volume de exceções de fato.
Para isso uma boa estratégia é analisar os Contadores de Performance. Em aplicações .NET Core podemos usar a ferramenta dotnet-counters para coletar esses contadores.
"dotnet-counters é uma ferramenta de monitoramento de desempenho para monitoramento de integridade ad hoc e investigação de desempenho de primeiro nível. Ele pode observar valores de contador de desempenho publicados por meio da EventCounter API. Por exemplo, você pode monitorar rapidamente coisas como o uso da CPU ou a taxa de exceções que está sendo gerada em seu aplicativo .NET Core para ver se há algo suspeito antes de mergulhar em uma investigação de desempenho mais séria usando PerfView ou dotnet-trace. Investigar contadores de desempenho (dotnet-counters)".
Coleta
Na máquina em que sua aplicação estiver rodando, instale dotnet-counters:
dotnet tool install -g dotnet-counters
Você também pode fazer download da ferramenta para um S.O específico, por exemplo: https://aka.ms/dotnet-counters/linux-x64.
Com ferramenta instalada precisamos:
- Descobrir o Process ID da aplicação que queremos realizar a coleta de dados.
- Realizar a coletar dos contadores de performance.
- Analisar a coleta e verificar o comportamento contadores: System.Runtime[exception-count],Microsoft.AspNetCore.Hosting[total-requests].
Para identificar o PID da aplicação rode o comando dotnet-counters ps e identifique o seu processo ASP.NET Core, no meu caso:
PS C:\> dotnet-counters ps
...
35896 EFMemoryLeak C:\EFMemoryLeak\EFMemoryLeak\bin\Release\net6.0\EFMemoryLeak.exe
...
Se a aplicação foi publicada no IIS, você pode procurar o PID usando o comando: netsh http show servicestate
Agora vamos realizar a coleta dos contadores, essa etapa é uma das mais importantes, pois uma vez realizado de forma equivocada toda a sua análise pode estar comprometida.
Para tal rodaremos o comando dotnet-counters collect:
dotnet-counters collect
-p 35896
--counters System.Runtime[exception-count],Microsoft.AspNetCore.Hosting[total-requests]
--refresh-interval 5
--format csv
Vamos desestruturar o comando acima para que você possa entender o que esta acontecendo aqui:
- collect: é o comando em si, a ferramenta dotnet-counters disponibiliza dois comandos: collect e monitor.
- -p: É a versão curta do parâmetro --process-id, e o valor 35896 é o PID que coletamos através do comando: dotnet-counters ps.
- --counters: Esse parâmetro é importante para coletarmos apenas provedores e contadores específicos, se não especificarmos ele assumirá o valor System.Runtime que coletaria todos os contadores de performance deste provedor, o que dificultaria nossa análise consideravelmente. Repare que estou coletando apenas os contadores de performance que de fato vão ajudar a identificar se a aplicação está com um alto volume de exceções ou não.
- --refresh-interval: Controla a periodicidade em segundos da atualização dos contadores que estão sendo coletados. É importante termos critério para definir esse número, por exemplo: Em coletas mais longas eu costumo aumenta-ló, para mitigar o risco do arquivo ficar muito grande, eu evito trabalhar com arquivo muito denso, pois ele dificulta o processo de transferir, abrir e manipular.
- --format: Define o formado do arquivo que será gerado, nesse caso vou analisa o resultado no Excel.
Nas versão atual da ferramenta dotnet-counters, ainda não é possível definir uma condição de finalização automática da coleta. Portanto essa tarefa cabe a nós.
Antes de rodar o comando se questione por quanto tempo você precisa que a coleta seja realizada, exemplo: Se sua aplicação tem picos de acesso entre as 12:00 e 15:00, talvez seja interessante realizar uma coleta durante todo o período de pico, para conseguir enxergar as nuances do comportamento dos contadores.
No meu caso vou deixar o comando rodando por uma hora consecutiva, depois manualmente vou para-lo.
Análise
Para parar o comando, acesse o terminal cujo você o executou e insira a letra q.
Depois de parar o comando, ele salvará um arquivo chamado counters.csv no mesmo diretório em que foi executado.
Antes de começarmos a analisar, faça você mesmo o questionamento: o que estamos procurando? A resposta para essa pergunta é que estamos buscando diagnosticar se a nossa aplicação está lançando mais exceções do que deveria. Um jeito simples de fazer isso é se realizarmos a seguinte fórmula entre os contadores.
TxE (Taxa de exceções) = Soma(exception-count)/Soma(total-requests).
Por exemplo: Em um cenário onde ocorreram 100 requisições e 100 lançamentos de exceções o valor de Tx seria igual a 1.
Agora abra o seu arquivo no Excel e realize as somas (meu foco aqui não é ensinar a usar a ferramenta Excel, portanto não comentarei sobre os passos envolvidos).
No meu caso:
- Soma(exception-count): 9236.
- Soma(total-requests): 12000.
A razão entre as duas somas é igual a 0,7696.
Isso significa que 76,96% das requisições estão lançando exceções? Não necessariamente pois em uma requisição pode haver mais de um lançamento de exceção.
De acordo com o livro Improving .NET Application Performance and Scalability se o valor da TxE estiver acima de 0,05 já devemos começar a nos preocupar. Observe que no meu caso o valor é 0,76, isso quer dize que a cada 10 requisições 7 exceções serão lançadas. Isso é uma catástrofe para o desempenho da aplicação.
"Este valor do contador deve ser inferior a 5% da solicitações para o aplicativo ASP.NET.". Trecho traduzido do livro Improving .NET Application Performance and Scalability página 705.
Vale lembrar que no ultimo artigo eu colo em mesa a reflexão: Se uma exceção especifica acontece com muita frequência, loga ela ja não é mais uma exceção.
Como podemos identificar quais as exceções estão sendo lançadas? Para isto existem algumas técnicas que podemos seguir, eu particularmente gosto de usar a ferramenta ProcDump.
ProcDump
Já sabemos que a aplicação está lançando muitas exceções em relação ao número de requisições, agora vamos concentrar os esforços em:
- Identificar o tipo de exceção que está sendo lançada com mais frequência.
- Capturar e analisar um Dump de memória procurando entender a causa raiz da exceção.
Vou pressupor que o PID do processo não tenha mudado e continua sendo 35896. Caso você tenha reiniciado o processo, é só refazer o passo que mostrei anteriormente:
PS C:\> dotnet-counters ps
...
35896 EFMemoryLeak C:\EFMemoryLeak\EFMemoryLeak\bin\Release\net6.0\EFMemoryLeak.exe
...
Faça o download do ProcDump através do link: https://docs.microsoft.com/sysinternals/downloads/procdump.
Vá até o diretório em que fez o download e execute o comando:
.\procdump.exe -accepteula -e 1 -f "" -p 35896
O comando é bem simples:
- -accepteula: Para aceitar automaticamente os termos de licença do SysInternals.
- -e: Para monitorarmos qualquer evento de exceção. Caso o parâmetro fosse -e 2 estaríamos monitorando apenas as exceções que derrubam o processo (o famoso Crash).
- -f: Podemos usar este parâmetro para filtrar exceções por tipo. No momento estamos passando uma string vazia, porém mais a frente usaremos ele.
- -p: Id do processo.
Este comando vai fazer uma espécie de monitoração no processo. Toda vez que uma exceção for lançada ele vai a registrar no terminal, portanto talvez você precise deixar esse comando rodando por um tempo, para que sua análise possa ser mais próxima à realidade.
O tempo necessário para deixar esse comando rodando pode mudar, eu costumo relacioná-lo à TxE (Taxa de exceções) que descobrimos anteriormente. No meu caso 76,96% das requisição estão lançando exceção, portanto não preciso de muito tempo. Deixei o comando rodando e fui tomar um café.
O resultado do comando foi:
[11:14:04] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:04] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:04] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:05] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:05] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:05] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:05] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:05] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:05] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:06] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:06] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:06] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:06] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:06] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:06] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:07] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:07] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:07] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:07] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:07] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:07] Exception: E0434F4D.System.Exception ("Invalid ID")
[11:14:08] Exception: E0434F4D.System.Exception ("Invalid ID")
Esse resultado vai variar de aplicação para aplicação, mas no meu caso significa que todas as exceções lançadas até o momento são do tipo System.Exception, ou seja, todas são exceções genéricas que receberam a string "Invalid ID" no seu construtor.
Nosso próximo passo é utilizar a ferramenta ProcDump para coletar um Dump de memória no momento em que essa exceção for lançada, para isso execute o comando:
.\procdump.exe -accepteula -ma -e 1 -f "System.Exception" 35896
- -accepteula: Para aceitar automaticamente os termos de licença do SysInternals.
- -ma: Para tirar um Minidump completo.
- -e: Para monitorarmos as exceções de primeira tentativa.
- -f: Filtramos apenas a exceção System.Exception para mitigar o risco de capturar um Dump no momento errado.
Repare também que não foi necessário passar o parâmetro -p, nessa caso passamos apenas o valor do PID. Isso se dá ao fato do parâmetro antecessor -ma dispensar a necessidade do parâmetro -p.
Agora é só esperar a mágica acontecer, ou seja, quando alguma exceção do tipo System.Exception for lançada o processo irá capturar um Dump de memória do qual poderemos depurar e entender o que está acontecendo.
Windbg
Abra o arquivo de Dump no Windbg e carregue o módulo contendo os comando que usaremos na depuração:
Certifique-se de que está abrindo o Windbg na mesma arquitetura do processo da aplicação do qual capturamos o Dump, exemplo: Se o processo era x64, abra o Windbg x64.
Para tal, rode os comandos:
!loadby sos clr
!load mex
Capturar o Dump com o comando do ProcDump que rodamos anteriormente facilita substancialmente nossa análise, pois temos certeza que o ponto de captura do Dump foi no evento de lançamento da exceção System.Exception, portanto podemos rodar o comando:
!analyze -v
O resultado vai ser longo, porém vou colocar os pontos específicos para os quais você deve se atentar:
*******************************************************************************
* *
* Exception Analysis *
* *
*******************************************************************************
...
PROCESS_NAME: EFMemoryLeak.exe
FAULTING_THREAD: ffffffff
STACK_TEXT:
000000d9`255bde80 00007ffb`e2840641 EFMemoryLeak!EFMemoryLeak.Controllers.PostController+<Post>d__5.MoveNext+0x2c1
...
FAULTING_SOURCE_LINE: C:\EFMemoryLeak\EFMemoryLeak\Controllers\PostController.cs
FAULTING_SOURCE_FILE: C:\source\repos\EFMemoryLeak\EFMemoryLeak\Controllers\PostController.cs
FAULTING_SOURCE_LINE_NUMBER: 47
FAULTING_SOURCE_CODE:
43: if (post.PostId == 0) throw new Exception("Invalid ID");
44:
45: await _blogContext.Posts.AddAsync(post);
46: await _blogContext.SaveChangesAsync();
> 47: }
48: catch {
49: return StatusCode(500);
50: }
51:
52:
Só com esse comando conseguimos o suficiente para encontrar a causa raiz da exceção.
Ela foi lançada PostController.cs e o catch estava na linha 47, ma linha 43 fica fácil de identificar o motivo da exceção:
Nota: No meu teste, o código fonte estava no mesmo diretório que a Dll compilada. Caso a sua Dll esteja em uma pasta diferente execute o comando .lsrcpath passando o diretório do código fonte, exemplo: .lsrcpath C:\source\repos\EFMemoryLeak\EFMemoryLeak.
43: if (post.PostId == 0) throw new Exception("Invalid ID");
Se a propriedade PostId do objeto Post for igual a 0 o código lança uma exceção.
Conclusão
Com as técnicas abordadas aqui você será capaz de descobrir a causa raiz de lançamento de exceções, sem precisar que sua aplicação esteja instrumentada para geração de logs e eventos. Isso pode ser extremamente relevante em casos de aplicações legadas, ou até mesmo em casos onde você não conhece muito bem a estrutura da aplicação que está analisando ou não pode confiar nos logs (O que acontece com frequência).
Microsoft
