Depurar a Privação de ThreadPool

Artigo
05/09/2023

Este artigo aplica-se a: ✔️ .NET Core 3.1 e versões posteriores

Neste tutorial, irá aprender a depurar um cenário de privação de ThreadPool. A desconsidão do ThreadPool ocorre quando o conjunto não tem threads disponíveis para processar novos itens de trabalho e, muitas vezes, faz com que as aplicações respondam lentamente. Com o exemplo fornecido ASP.NET Core aplicação Web, pode causar a privação intencional do ThreadPool e aprender a diagnosticá-la.

Neste tutorial, vai:

Investigar uma aplicação que está a responder lentamente aos pedidos
A utilização da ferramenta dotnet-counters para identificar a fome do ThreadPool está provavelmente a ocorrer
Utilize a ferramenta dotnet-stack para determinar que trabalho está a manter os threads do ThreadPool ocupados

Pré-requisitos

O tutorial utiliza:

SDK .NET Core 6.0 para compilar e executar a aplicação de exemplo
Exemplo de aplicação Web para demonstrar o comportamento de fome do ThreadPool
Bombardier para gerar carga para a aplicação Web de exemplo
dotnet-counters para observar contadores de desempenho
dotnet-stack para examinar pilhas de threads

Executar a aplicação de exemplo

Transfira o código da aplicação de exemplo e crie-o com o SDK .NET:

E:\demo\DiagnosticScenarios>dotnet build
Microsoft (R) Build Engine version 17.1.1+a02f73656 for .NET
Copyright (C) Microsoft Corporation. All rights reserved.

  Determining projects to restore...
  All projects are up-to-date for restore.
  DiagnosticScenarios -> E:\demo\DiagnosticScenarios\bin\Debug\net6.0\DiagnosticScenarios.dll

Build succeeded.
    0 Warning(s)
    0 Error(s)

Time Elapsed 00:00:01.26

Execute a aplicação:

E:\demo\DiagnosticScenarios>bin\Debug\net6.0\DiagnosticScenarios.exe
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: http://localhost:5000
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: https://localhost:5001
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Production
info: Microsoft.Hosting.Lifetime[0]
      Content root path: E:\demo\DiagnosticScenarios

Se utilizar um browser e enviar pedidos para https://localhost:5001/api/diagscenario/taskwaito , deverá ver a resposta success:taskwait devolvida após cerca de 500 ms. Isto mostra que o servidor Web está a servir o tráfego conforme esperado.

Observar um desempenho lento

O servidor Web de demonstração tem vários pontos finais que simulam fazer um pedido de base de dados e, em seguida, devolver uma resposta ao utilizador. Cada um destes pontos finais tem um atraso de aproximadamente 500 ms ao servir pedidos um de cada vez, mas o desempenho é muito pior quando o servidor Web está sujeito a alguma carga. Transfira a ferramenta de teste de carga Bombardier e observe a diferença de latência quando 125 pedidos simultâneos são enviados para cada ponto final.

bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait
Bombarding https://localhost:5001/api/diagscenario/taskwait for 10s using 125 connection(s)
[=============================================================================================] 10s
Done!
Statistics        Avg      Stdev        Max
  Reqs/sec        33.06     234.67    3313.54
  Latency         3.48s      1.39s     10.79s
  HTTP codes:
    1xx - 0, 2xx - 454, 3xx - 0, 4xx - 0, 5xx - 0
    others - 0
  Throughput:    75.37KB/s

Este segundo ponto final utiliza um padrão de código que tem um desempenho ainda pior:

bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/tasksleepwait
Bombarding https://localhost:5001/api/diagscenario/tasksleepwait for 10s using 125 connection(s)
[=============================================================================================] 10s
Done!
Statistics        Avg      Stdev        Max
  Reqs/sec         1.61      35.25     788.91
  Latency        15.42s      2.18s     18.30s
  HTTP codes:
    1xx - 0, 2xx - 140, 3xx - 0, 4xx - 0, 5xx - 0
    others - 0
  Throughput:    36.57KB/s

Ambos os pontos finais mostram significativamente mais do que a latência média de 500 ms quando a carga é elevada (3,48 s e 15,42 s, respetivamente). Se executar este exemplo numa versão mais antiga do .NET Core, é provável que ambos os exemplos funcionem igualmente mal. O .NET 6 atualizou a heurística de ThreadPool que reduz o impacto no desempenho do padrão de codificação incorreto utilizado no primeiro exemplo.

Detetar a fome do ThreadPool

Se observasse o comportamento acima num serviço do mundo real, saberia que está a responder lentamente sob carga, mas não saberia a causa. O dotnet-counters é uma ferramenta que pode mostrar contadores de desempenho em direto. Estes contadores podem fornecer pistas sobre certos problemas e são muitas vezes fáceis de obter. Em ambientes de produção, poderá ter contadores semelhantes fornecidos por ferramentas de monitorização remota e dashboards Web. Instale contadores dotnet e comece a monitorizar o serviço Web:

dotnet-counters monitor -n DiagnosticScenarios
Press p to pause, r to resume, q to quit.
    Status: Running

[System.Runtime]
    % Time in GC since last GC (%)                                 0
    Allocation Rate (B / 1 sec)                                    0
    CPU Usage (%)                                                  0
    Exception Count (Count / 1 sec)                                0
    GC Committed Bytes (MB)                                        0
    GC Fragmentation (%)                                           0
    GC Heap Size (MB)                                             34
    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)                                      279,021
    LOH Size (B)                                                   0
    Monitor Lock Contention Count (Count / 1 sec)                  0
    Number of Active Timers                                        0
    Number of Assemblies Loaded                                  121
    Number of Methods Jitted                                   3,223
    POH (Pinned Object Heap) Size (B)                              0
    ThreadPool Completed Work Item Count (Count / 1 sec)           0
    ThreadPool Queue Length                                        0
    ThreadPool Thread Count                                        1
    Time spent in JIT (ms / 1 sec)                                 0.387
    Working Set (MB)                                              87

Os contadores acima são um exemplo, enquanto o servidor Web não estava a servir pedidos. Execute Bombardier novamente com o api/diagscenario/tasksleepwait ponto final e carga sustentada durante 2 minutos, pelo que há muito tempo para observar o que acontece aos contadores de desempenho.

bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/tasksleepwait -d 120s

A eliminação de threadPool ocorre quando não existem threads gratuitos para processar os itens de trabalho em fila e o runtime responde aumentando o número de threads threadPool. Deve observar o ThreadPool Thread Count aumento rápido para 2-3x o número de núcleos de processador no seu computador e, em seguida, são adicionados mais threads 1 a 2 por segundo até que, eventualmente, estabilizem algures acima de 125. O aumento lento e constante dos threads threadPool combinado com a Utilização da CPU muito inferior a 100% são os principais sinais de que a fome do ThreadPool é atualmente um estrangulamento de desempenho. O aumento da contagem de threads continuará até que o conjunto atinja o número máximo de threads, tenham sido criados threads suficientes para satisfazer todos os itens de trabalho recebidos ou a CPU tenha sido saturada. Muitas vezes, mas nem sempre, a fome de ThreadPool também mostrará grandes valores para ThreadPool Queue Length e valores baixos para ThreadPool Completed Work Item Count, o que significa que há uma grande quantidade de trabalho pendente e pouco trabalho a ser concluído. Eis um exemplo dos contadores enquanto a contagem de threads continua a aumentar:

Press p to pause, r to resume, q to quit.
    Status: Running

[System.Runtime]
    % Time in GC since last GC (%)                                 0
    Allocation Rate (B / 1 sec)                               24,480
    CPU Usage (%)                                                  0
    Exception Count (Count / 1 sec)                                0
    GC Committed Bytes (MB)                                       56
    GC Fragmentation (%)                                          40.603
    GC Heap Size (MB)                                             89
    Gen 0 GC Count (Count / 1 sec)                                 0
    Gen 0 Size (B)                                         6,306,160
    Gen 1 GC Count (Count / 1 sec)                                 0
    Gen 1 Size (B)                                         8,061,400
    Gen 2 GC Count (Count / 1 sec)                                 0
    Gen 2 Size (B)                                               192
    IL Bytes Jitted (B)                                      279,263
    LOH Size (B)                                              98,576
    Monitor Lock Contention Count (Count / 1 sec)                  0
    Number of Active Timers                                      124
    Number of Assemblies Loaded                                  121
    Number of Methods Jitted                                   3,227
    POH (Pinned Object Heap) Size (B)                      1,197,336
    ThreadPool Completed Work Item Count (Count / 1 sec)           2
    ThreadPool Queue Length                                       29
    ThreadPool Thread Count                                       96
    Time spent in JIT (ms / 1 sec)                                 0
    Working Set (MB)                                             152

Uma vez estabilizada a contagem de threads threadPool, a piscina deixa de estar esfomeada. No entanto, se estabilizar a um valor elevado (mais do que três vezes o número de núcleos do processador), isso normalmente indica que o código da aplicação está a bloquear alguns threads threadPool e o ThreadPool está a compensar ao executar com mais threads. A execução estável em contagens de threads elevadas não terá necessariamente grandes impactos na latência do pedido, mas se a carga variar drasticamente ao longo do tempo ou a aplicação for reiniciada periodicamente, sempre que o ThreadPool for susceptível de entrar num período de fome em que está lentamente a aumentar os threads e a fornecer latência de pedido fraca. Cada thread também consome memória, pelo que reduzir o número total de threads necessários proporciona outro benefício.

A partir do .NET 6, a heurística threadPool foi modificada para aumentar verticalmente o número de threads threadPool muito mais rapidamente em resposta a determinadas APIs de Tarefas de bloqueio. A supressão do ThreadPool ainda pode ocorrer com estas APIs, mas a duração é muito mais breve do que com versões mais antigas do .NET, porque o runtime responde mais rapidamente. Execute Bombardier novamente com o api/diagscenario/taskwait ponto final:

bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s

No .NET 6, deve observar que o conjunto aumenta a contagem de threads mais rapidamente do que antes e, em seguida, estabiliza num número elevado de threads. A fome do ThreadPool está a ocorrer enquanto a contagem de threads está a subir.

Resolver a fome de ThreadPool

Para eliminar a supressão do ThreadPool, os threads de ThreadPool têm de permanecer desbloqueados para que estejam disponíveis para processar itens de trabalho recebidos. Existem duas formas de determinar o que cada thread estava a fazer, seja através da ferramenta dotnet-stack ou ao capturar uma captura com dotnet-dump que pode ser visualizada no Visual Studio. O dotnet-stack pode ser mais rápido porque mostra as pilhas de threads imediatamente na consola, mas a depuração da captura do Visual Studio oferece melhores visualizações que mapeiam frames à origem, o Just My Code pode filtrar frames de implementação de runtime e a funcionalidade Pilhas Paralelas pode ajudar a agrupar um grande número de threads com pilhas semelhantes. Este tutorial mostra a opção dotnet-stack. Veja o vídeo do tutorial de diagnóstico de threadPool para obter um exemplo de investigação das pilhas de threads com o Visual Studio.

Execute o Bombardier novamente para colocar o servidor Web sob carga:

bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s

Em seguida, execute dotnet-stack para ver os rastreios da pilha de threads:

dotnet-stack report -n DiagnosticScenarios

Deverá ver uma saída longa que contém um grande número de pilhas, muitas das quais têm o seguinte aspeto:

Thread (0x25968):
  [Native Frames]
  System.Private.CoreLib.il!System.Threading.ManualResetEventSlim.Wait(int32,value class System.Threading.CancellationToken)
  System.Private.CoreLib.il!System.Threading.Tasks.Task.SpinThenBlockingWait(int32,value class System.Threading.CancellationToken)
  System.Private.CoreLib.il!System.Threading.Tasks.Task.InternalWaitCore(int32,value class System.Threading.CancellationToken)
  System.Private.CoreLib.il!System.Threading.Tasks.Task`1[System.__Canon].GetResultCore(bool)
  DiagnosticScenarios!testwebapi.Controllers.DiagScenarioController.TaskWait()
  Anonymously Hosted DynamicMethods Assembly!dynamicClass.lambda_method1(pMT: 00007FF7A8CBF658,class System.Object,class System.Object[])
  Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor+SyncObjectResultExecutor.Execute(class Microsoft.AspNetCore.Mvc.Infrastructure.IActionResultTypeMapper,class Microsoft.Extensions.Internal.ObjectMethodExecutor,class System.Object,class System.Object[])
  Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeActionMethodAsync()
  Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(value class State&,value class Scope&,class System.Object&,bool&)
  Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()
  Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(value class State&,value class Scope&,class System.Object&,bool&)
  Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()
  Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(value class State&,value class Scope&,class System.Object&,bool&)
  Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()
  Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(value class State&,value class Scope&,class System.Object&,bool&)
  Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeFilterPipelineAsync()
  Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeAsync()
  Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Routing.ControllerRequestDelegateFactory+<>c__DisplayClass10_0.<CreateRequestDelegate>b__0(class Microsoft.AspNetCore.Http.HttpContext)
  Microsoft.AspNetCore.Routing.il!Microsoft.AspNetCore.Routing.EndpointMiddleware.Invoke(class Microsoft.AspNetCore.Http.HttpContext)
  Microsoft.AspNetCore.Authorization.Policy.il!Microsoft.AspNetCore.Authorization.AuthorizationMiddleware+<Invoke>d__6.MoveNext()
  System.Private.CoreLib.il!System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start(!!0&)
  Microsoft.AspNetCore.Authorization.Policy.il!Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(class Microsoft.AspNetCore.Http.HttpContext)
  Microsoft.AspNetCore.HttpsPolicy.il!Microsoft.AspNetCore.HttpsPolicy.HttpsRedirectionMiddleware.Invoke(class Microsoft.AspNetCore.Http.HttpContext)
  Microsoft.AspNetCore.HttpsPolicy.il!Microsoft.AspNetCore.HttpsPolicy.HstsMiddleware.Invoke(class Microsoft.AspNetCore.Http.HttpContext)
  Microsoft.AspNetCore.HostFiltering.il!Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware.Invoke(class Microsoft.AspNetCore.Http.HttpContext)
  Microsoft.AspNetCore.Server.Kestrel.Core.il!Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol+<ProcessRequests>d__223`1[System.__Canon].MoveNext()
  System.Private.CoreLib.il!System.Threading.ExecutionContext.RunInternal(class System.Threading.ExecutionContext,class System.Threading.ContextCallback,class System.Object)
  System.Private.CoreLib.il!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[System.Threading.Tasks.VoidTaskResult,Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol+<ProcessRequests>d__223`1[System.__Canon]].MoveNext(class System.Threading.Thread)
  System.Private.CoreLib.il!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(class System.Runtime.CompilerServices.IAsyncStateMachineBox,bool)
  System.Private.CoreLib.il!System.Threading.Tasks.Task.RunContinuations(class System.Object)
  System.IO.Pipelines.il!System.IO.Pipelines.StreamPipeReader+<<ReadAsync>g__Core|36_0>d.MoveNext()
  System.Private.CoreLib.il!System.Threading.ExecutionContext.RunInternal(class System.Threading.ExecutionContext,class System.Threading.ContextCallback,class System.Object)
  System.Private.CoreLib.il!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[System.IO.Pipelines.ReadResult,System.IO.Pipelines.StreamPipeReader+<<ReadAsync>g__Core|36_0>d].MoveNext(class System.Threading.Thread)
  System.Private.CoreLib.il!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(class System.Runtime.CompilerServices.IAsyncStateMachineBox,bool)
  System.Private.CoreLib.il!System.Threading.Tasks.Task.RunContinuations(class System.Object)
  System.Private.CoreLib.il!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[System.Int32].SetExistingTaskResult(class System.Threading.Tasks.Task`1<!0>,!0)
  System.Net.Security.il!System.Net.Security.SslStream+<ReadAsyncInternal>d__186`1[System.Net.Security.AsyncReadWriteAdapter].MoveNext()
  System.Private.CoreLib.il!System.Threading.ExecutionContext.RunInternal(class System.Threading.ExecutionContext,class System.Threading.ContextCallback,class System.Object)
  System.Private.CoreLib.il!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[System.Int32,System.Net.Security.SslStream+<ReadAsyncInternal>d__186`1[System.Net.Security.AsyncReadWriteAdapter]].MoveNext(class System.Threading.Thread)
  Microsoft.AspNetCore.Server.Kestrel.Core.il!Microsoft.AspNetCore.Server.Kestrel.Core.Internal.DuplexPipeStream+<ReadAsyncInternal>d__27.MoveNext()
  System.Private.CoreLib.il!System.Threading.ExecutionContext.RunInternal(class System.Threading.ExecutionContext,class System.Threading.ContextCallback,class System.Object)
  System.Private.CoreLib.il!System.Threading.ThreadPoolWorkQueue.Dispatch()
  System.Private.CoreLib.il!System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()

Os fotogramas na parte inferior destas pilhas indicam que estes threads são threads threadpool:

  System.Private.CoreLib.il!System.Threading.ThreadPoolWorkQueue.Dispatch()
  System.Private.CoreLib.il!System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()

E os fotogramas junto à parte superior revelam que o thread está bloqueado numa chamada a GetResultCore(bool) partir da função DiagnosticScenarioController.TaskWait():

Thread (0x25968):
  [Native Frames]
  System.Private.CoreLib.il!System.Threading.ManualResetEventSlim.Wait(int32,value class System.Threading.CancellationToken)
  System.Private.CoreLib.il!System.Threading.Tasks.Task.SpinThenBlockingWait(int32,value class System.Threading.CancellationToken)
  System.Private.CoreLib.il!System.Threading.Tasks.Task.InternalWaitCore(int32,value class System.Threading.CancellationToken)
  System.Private.CoreLib.il!System.Threading.Tasks.Task`1[System.__Canon].GetResultCore(bool)
  DiagnosticScenarios!testwebapi.Controllers.DiagScenarioController.TaskWait()

Agora, pode navegar para o código deste controlador no ficheiro Controllers/DiagnosticScenarios.cs da aplicação de exemplo para ver que está a chamar uma API assíncrona sem utilizar await. Este é o padrão de código sincronizado sobre assíncrono , que é conhecido por bloquear threads e é a causa mais comum de fome de ThreadPool.

public ActionResult<string> TaskWait()
{
    // ...
    Customer c = PretendQueryCustomerFromDbAsync("Dana").Result;
    return "success:taskwait";
}

Neste caso, o código pode ser facilmente alterado para utilizar assíncrona/aguardar, conforme mostrado no TaskAsyncWait() ponto final. A utilização do await permite que o thread atual aguarde outros itens de trabalho enquanto a consulta da base de dados estiver em curso. Quando a pesquisa da base de dados estiver concluída, um thread ThreadPool retomará a execução. Desta forma, nenhum thread é bloqueado no código durante cada pedido:

public async Task<ActionResult<string>> TaskAsyncWait()
{
    // ...
    Customer c = await PretendQueryCustomerFromDbAsync("Dana");
    return "success:taskasyncwait";
}

A execução de Bombadier para enviar carga para o api/diagscenario/taskasyncwait ponto final mostra que a contagem de threads de ThreadPool permanece muito mais baixa e a latência média permanece próxima dos 500ms ao utilizar a abordagem assíncrona/de espera:

>bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskasyncwait
Bombarding https://localhost:5001/api/diagscenario/taskasyncwait for 10s using 125 connection(s)
[=============================================================================================] 10s
Done!
Statistics        Avg      Stdev        Max
  Reqs/sec       227.92     274.27    1263.48
  Latency      532.58ms    58.64ms      1.14s
  HTTP codes:
    1xx - 0, 2xx - 2390, 3xx - 0, 4xx - 0, 5xx - 0
    others - 0
  Throughput:    98.81KB/s

Partilhar via