Threadpool no aspnet e problemas de performance

Quando uma requisição passa maior parte do seu tempo aguardando o resultado de operações de entrada e saída, como banco de dados ou requisições para outras APIs, ela é considerada I/O bound.

Considere o seguinte trecho de código C#, que executa uma consulta ao banco de dados.

_context.Customers.FirstOrDefault(x => x.Id = id)

O que acontece nesse cenário é que a thread sendo executada é bloqueada ao executar a chamada remota e só será desbloqueada quando o resultado da requisição estiver disponível. Logo, outras requisições dessa API precisam ser executadas em outras threads. Se não houverem threads disponíveis no momento as outras requisições devem esperar.

Para melhorar a performance de aplicações desse tipo o dotnet disponibiliza o tipo Task que representa uma operação normalmente executada de forma assíncrona.

O cenário anterior foi modificado para usar programação assíncrona.

await _context.Customers.FirstOrDefaultAsync(x => x.Id = id)

Quando usamos o async/await a thread corrente não é bloqueada como no cenário anterior. As threads são reaproveitadas ao invés de bloqueadas, o que permite que mais requisições possam ser processadas de forma concorrente. Quando usamos Task e o async/await por baixo dos panos uma callback é registrada e executada quando o resultado da operação de IO é retornada.

Threadpool starvation

A criação e destruição de threads é um processo caro ao sistema operacional. Por esse motivo o dotnet disponibiliza o threadpool, que é um conjunto de threads que foram criadas e são disponibilizadas para uso. Quando necessário novas threads podem ser criadas pelo threadpool do dotnet mas numa taxa limitada (um ou duas por segundo).

O cenário em que a quantidade de tarefas aguardando a liberação de threads aumenta em uma taxa maior que a de criação de novas threads é chamado de threadpool starvation. As requisições são enfileiradas aguardando a sua vez para serem processadas impactando a performance da aplicação.

Os sintomas de aplicação nesse estado é o aumento do número de threads enquanto ainda há capacidade de CPU disponível.
Uma maneira para diagnosticar APIs no estado de threadpool starvation é observar as seguintes métricas:

• threadpool-queue-length: O número de itens de trabalho que estão enfileirados, no momento, para serem processados no ThreadPool
• threadpool-thread-count: O número de threads do pool de threads que existem no momento no ThreadPool, com base em ThreadPool.ThreadCount
• threadpool-completed-items-count: O número de itens de trabalho processados no ThreadPool

O saudável seria o número de threads constante, a fila se mantendo zerada e o número de itens processados alto.

Exemplo

Como laboratório para analisar as métricas de performance em um cenário saudável e em threadpool starvation serão usadas duas ferramentas:

1. dotnet-counters: uma ferramenta para análise de performance e saúde de aplicações dotnet. Permite observar valores de contadores de performance.
2. hey: gerador de carga para aplicações web.

O código da aplicação de teste e todo o setup das ferramentas usando docker está disponível no github. A aplicação possui dois endpoints que executam chamadas no banco de dados em uma operação de duração de 500 milissegundos, para simular um cenário com maior latência. O endpoint sync utiliza a API síncrona e o async a API assíncrona:

[HttpGet("sync")]
public IActionResult GetSync()
{
    _context.Database.ExecuteSqlRaw("WAITFOR DELAY '00:00:00.500'");
    return Ok();
}

[HttpGet("async")]
public async Task<IActionResult> GetAsync()
{
    await _context.Database.ExecuteSqlRawAsync("WAITFOR DELAY '00:00:00.500'");
    return Ok();
}

Para iniciar aplicação e o monitoramento com o dotnet-counters devem ser executados os seguintes comandos:

docker compose up app
docker exec -it thread-pool-test-app dotnet-counters monitor -n dotnet

O teste de carga usando o endpoint sync:

docker compose up send-load-sync

O resultado simplificado do teste carga e um snapshot do dotnet-counters é aprensentado abaixo.

 Summary:
   Total:    27.2940 secs
   Slowest:  5.1772 secs
   Fastest:  0.5020 secs
   Average:  2.6085 secs
   Requests/sec:     36.6380

[System.Runtime]
    % Time in GC since last GC (%)                              0
    Allocation Rate (B / 1 sec)                         2,987,784
    CPU Usage (%)                                               0
    Exception Count (Count / 1 sec)                             0
    GC Committed Bytes (MB)                                     0
    GC Fragmentation (%)                                        0
    GC Heap Size (MB)                                         109
    Gen 0 GC Count (Count / 1 sec)                              0
    Gen 0 Size (B)                                              0
    Gen 1 GC Count (Count / 1 sec)                              0
    Gen 1 Size (B)                                              0
    Gen 2 GC Count (Count / 1 sec)                              0
    Gen 2 Size (B)                                              0
    IL Bytes Jitted (B)                                   797,595
    LOH Size (B)                                                0
    Monitor Lock Contention Count (Count / 1 sec)              11
    Number of Active Timers                                     3
    Number of Assemblies Loaded                               152
    Number of Methods Jitted                               10,503
    POH (Pinned Object Heap) Size (B)                           0
    ThreadPool Completed Work Item Count (Count / 1 sec)       55
    ThreadPool Queue Length                                    74
    ThreadPool Thread Count                                    36
    Time spent in JIT (ms / 1 sec)                              0.656
    Working Set (MB)                                          232

O teste de carga usando o endpoint async:

docker compose up send-load-async

Os resultados:

 Summary:
   Total:   5.5532 secs
   Slowest: 1.0283 secs
   Fastest: 0.5011 secs
   Average: 0.5272 secs
   Requests/sec:    180.0777

[System.Runtime]
    % Time in GC since last GC (%)                              0
    Allocation Rate (B / 1 sec)                         4,458,328
    CPU Usage (%)                                               0
    Exception Count (Count / 1 sec)                             0
    GC Committed Bytes (MB)                                     0
    GC Fragmentation (%)                                        0
    GC Heap Size (MB)                                         114
    Gen 0 GC Count (Count / 1 sec)                              0
    Gen 0 Size (B)                                              0
    Gen 1 GC Count (Count / 1 sec)                              0
    Gen 1 Size (B)                                              0
    Gen 2 GC Count (Count / 1 sec)                              0
    Gen 2 Size (B)                                              0
    IL Bytes Jitted (B)                                   825,928
    LOH Size (B)                                                0
    Monitor Lock Contention Count (Count / 1 sec)              10
    Number of Active Timers                                     3
    Number of Assemblies Loaded                               152
    Number of Methods Jitted                               10,947
    POH (Pinned Object Heap) Size (B)                           0
    ThreadPool Completed Work Item Count (Count / 1 sec)    1,384
    ThreadPool Queue Length                                     0
    ThreadPool Thread Count                                    30
    Time spent in JIT (ms / 1 sec)                              3.467
    Working Set (MB)                                          236

Comparando as duas versões é possível ver que a versão sync tem chamadas lentas causadas pelo tempo de espera da requisição para ser processada. Durante todo o teste o ThreadPool Queue Length se manteve alto.

A versão async tem uma média de chamadas próximo ao tempo de 500 milissegundos que é o esperado para cada requisição e o ThreadPool Queue Length se mantem próximo a 0 durante o teste. O ThreadPool Completed Work Item Counté bem maior comparado ao cenário sync.

Conclusão

A programação assíncrona, ao reutilizar threads ao invés de bloqueá-las, permite aumentar a quantidade de requisições capaz de serem processadas em aplicações com características IO bound. No dotnet isso é feito usando o async/await.

Em uma aplicação real pode não ser simples identificar operações blocantes que podem levar a problemas de performance em um cenário de grande quantidade de requisições. Para isso, pode ser usada a ferramenta dotnet-counters somado à um teste de carga para diagnosticar possíveis cenários de thread starvation.