Depurar um problema de desempenho em aplicações hospedadas no Azure App Service (Serviços de Aplicativos) pode ser uma tarefa desafiadora, porém com as ferramentas certas você será capaz de encontrar gargalos de performance nas suas aplicações. Neste artigo vou mostrar um caso fictício de depuração de uma Web API publicada em Serviço de Aplicativo do Azure.
Ambiente
- Web API ASP.NET Core 6.0 publicada em um Serviço de Aplicativo Azure.
- Area de trabalho no Azure Applications Insights.
Observação. Você pode reproduzir todo o cenário apresentado neste artigo clonando o repositório do GitHub ThreadPoolExhaustApi.
Cenário
A Web API contém apenas um endpoint acessado através da URL [https://localhost/weatherforecast]. Esse endpoint demora em média 150 milissegundos para responder, porém em cenários de alta demanda esse tempo pode ultrapassar 2 segundos.
Application Insights
Para analisar o comportamento da aplicação, utilizaremos o Application Insights.
Dentro da área de trabalho do Insights existe uma tela chamada Performance que fornece várias métricas de desempenho da nossa aplicação. Vamos abrir essa tela e em seguida configurar o filtro de datas para quando ocorreu a suposta lentidão.
No período selecionado nosso endpoint foi requisitado aproximadamente 62 mil vezes e com um tempo de resposta médio de 484 milissegundos.
Ainda nessa mesma tela, podemos observar uma distribuição no tempo de resposta, conforme a imagem abaixo.
A grande maioria das requisições ficaram com um tempo de resposta entre 170 e 440 milissegundos, mas várias requisições que ficaram fora dessa faixa, essas requisições que precisamos investigar melhor. Podemos usar os filtros do portal para isolar as requisições mais lentas e depois exportar para um relatório. Isso vai ajudar a entender se existe algum padrão entre essas requisições lentas.
Encontramos 193 requisições que demoraram mais que 940 milissegundos, ao clicar no botão drill into, somos redirecionados para uma outra tela, que irá listar as requisições filtradas.
Um padrão interessante que podemos observar, é que todas essas requisições acontecerem em um intervalo de tempo muito curto, onde a primeira requisição aconteceu as 20:04:48 e a última as 20:05:24. Portanto tivemos uma carga de aproximadamente 200 requisições em um intervalo de tempo de apenas 36 segundos.
Nesse primeiro momento podemos concluir que o nosso problema acontece quando recebemos muitas requisições em um curto intervalo de tempo, em outras palavras, a concorrência está ocasionando essa lentidão.
Em alguns cenários, essa lentidão pode ser justificada pelo consumo de CPU, e nesse caso nossa solução seria escalar essa aplicação, criando mais instâncias nesses momentos de alta demanda, mas será que a aplicação consumiu muita CPU?
Agora que sabemos o horário de pico, ainda no Application Insights precisamos navegar até a tela chamada Metrics, nela podemos ver um histórico de consumo de CPU da nossa aplicação.
Para isso basta configurar:
- Filtro do tempo: de 22/03/2022 20:00 até 22/03/2022 20:10.
- Métrica: Process CPU (all cores).
O filtro de tempo foi configurado para alguns minutos antes e depois da lentidão para conseguirmos enxergar a atenuação do gráfico de consumo de CPU.
Fazendo isso conseguimos entender se nossa aplicação demandou mais CPU do que o disponível, e isso justificaria esse tempo de resposta alto.
Porém como evidente nessa última imagem, mesmo no momento de pico, nossa aplicação consumiu 62% de CPU o que não justifica o tempo de resposta das requisições.
Ainda não conseguimos identificar a causa raiz desta lentidão, porém conseguimos descartar a hipótese do problema estar relacionado ao consumo de CPU.
Auto-Heal
Agora que entendemos o padrão de comportamento da API em um cenário de alta demanda, o próximo passo é coletar um Dump para conseguir chegar à causa raiz do problema.
A melhor forma de coletar um Dump em um Serviço de Aplicativo é usando uma funcionalidade da plataforma chamada Auto-Heal, com ela podemos configurar um gatilho para coletar nosso Dump no momento mais adequado.
Para configurar esse gatilho, basta entrar no Serviço de Aplicativo pelo portal do Azure, e acessar a tela chamada Diagnose and Solve Problems, nesta tela navegaremos até o ponto de configuração do nosso gatilho.
Vamos configurar o gatilho para tirar o Dump quando 2 requisições demorarem mais que 2 segundos em um intervalo de 10 segundos.
Para coletar o Dump usaremos uma funcionalidade do Azure chamada DaaS (Diagnostics as a Service), ele será responsável pela coleta e pela transferência do arquivo para uma Conta de Armazenamento do Azure.
Agora precisamos esperar que o problema aconteça novamente, quando isso acontecer o dump será coletado e poderemos analisá-lo.
Quando o gatilho disparar, basta clicar em View All Sessions e baixar o Dump.
Análise
Agora com o arquivo de Dump em mãos, vamos abri-lo com o Visual Studio. Poderíamos escolher outras ferramentas para depuração, como o WinDbg, porém o Visual Studio facilita o processo.
Com o arquivo aberto no Visual Studio, vamos clicar em Debug with Managed Only, e esperar carregar todos os símbolos.
Vamos abrir uma tela chamada Parallel Stacks, essa tela é muito útil, pois ela agrupa de forma visual todas as threads por pilha de chamadas. Com isso conseguimos identificar facilmente os padrões de processamento.
Agora nessa tela navegaremos entre as pilhas, procurando algum padrão. Nesse caso o que mais me chamou a atenção foi uma pilha que se repetiu em 84 threads.
Podemos observar que nessa pilha existe as chamadas dos métodos:
WeatherForecastController.Get;WeatherForecastService.GetAsync;WeatherForecastRepository.GetAsync;
Dentro desta tela, podemos dar um duplo clique em qualquer uma dessas linhas, o a IDE irá no mostrar o código que estava em execução.
Vamos dar um duplo clique em WeatherForecastController.Get:
Podemos observar nesse caso o uso do modificador async, e do operador await.
Agora vamos dar um duplo clique em WeatherForecastService.GetAsync:
Aqui também se faz o uso do async/await.
Agora vamos dar um duplo clique em WeatherForecastRepository.GetAsync:
Nesse caso o método implementa o modificador async, mas não usa o operador await.
Pela falta da implementação do operador await que a nossa aplicação não consegue lidar com um grande volume de chamadas simultâneas. A linha que implementa Task.Delay(150).Wait(); irá bloquear a thread por 150 milissegundos (isso simulará uma chamada a um recurso bloqueante, por exemplo: Banco de Dados), e esse thread não poderá fazer mais nada, o que é bem ruim, pois no modelo assíncrono, essa thread poderia retornar para o threadpool para processar outras requisições.
No artigo Como melhorar a performance de uma Web API ASP.NET Core usando async/await descrevo esse comportamento com bastante riqueza de detalhes o porque ele acaba piorando o desempenho da nossa aplicação.
Conclusão
Usando as ferramentas certas, conseguimos de forma rápida e eficiente depurar uma aplicação que apresenta lentidão, ou até mesmo outros problemas.
No caso deste artigo a nossa aplicação não estava implementando de forma apropriada o modelo de programação assíncrona, gerando um bloqueio de threads, e fazendo com que o desempenho da aplicação não fosse bom em um momento de alta demanda de requisições.
Uma simples refatoração substituindo o método Wait pelo operador await já melhoria muito o desempenho dessa aplicação.
await Task.Delay(150);
Portanto, se você está usando o modelo de programação assíncrona, certifique-se de sempre estar usando o modificador async e o operador await de forma apropriada e principalmente evite o uso de métodos/propriedades bloqueantes, como o Task.Result e Task.Wait.
