Depurar a privação do ThreadPool
Este artigo se aplica a: ✔️ SDK do .NET Core 3.1 e versões posteriores
Neste tutorial, você aprenderá a depurar um cenário de privação do ThreadPool. A privação do ThreadPool ocorre quando o pool não tem threads disponíveis para processar novos itens de trabalho e costuma causar lentidão na resposta dos aplicativos. Usando o exemplo de aplicativo Web do ASP.NET Core fornecido, você pode causar privação do ThreadPool intencionalmente e aprender a diagnosticá-lo.
Neste tutorial, você irá:
- Investigar um aplicativo que está respondendo às solicitações com lentidão
- Usar a ferramenta dotnet-counters para identificar se a privação do ThreadPool está ocorrendo
- Usar a ferramenta dotnet-stack para determinar qual trabalho está mantendo os threads do ThreadPool ocupados
Pré-requisitos
O tutorial usa:
- SDK do .NET Core 6.0 para compilar e executar o aplicativo de exemplo
- O aplicativo Web de exemplo para demonstrar o comportamento de privação do ThreadPool
- O Bombardier que vai gerar uma carga para o aplicativo Web de exemplo
- O dotnet-counters para observar os contadores de desempenho
- O dotnet-stack para examinar as pilhas de thread
Executando o aplicativo de exemplo
Baixe o código do aplicativo de exemplo e compile-o usando o SDK do .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.26Executar o aplicativo:
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 você usar um navegador da Web e enviar solicitações para https://localhost:5001/api/diagscenario/taskwait, verá a resposta success:taskwait retornada após cerca de 500 ms. Isso mostra que o servidor Web está fornecendo o tráfego conforme o esperado.
Como observar o desempenho lento
O servidor Web de demonstração tem vários pontos de extremidade que simulam uma solicitação de banco de dados e depois retornam uma resposta ao usuário. Cada um desses pontos de extremidade tem um atraso de cerca de 500 ms ao atender a uma solicitação de cada vez, mas o desempenho é muito pior quando o servidor Web é submetido a alguma carga. Baixe a ferramenta de teste de carga Bombardier e observe a diferença de latência quando 125 solicitações simultâneas são enviadas a cada ponto de extremidade.
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 de extremidade usa 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
Os dois pontos de extremidade mostram uma latência extremamente maior do que a média de 500 ms quando a carga é alta (3,48 s e 15,42 s, respectivamente). Se você executar este exemplo em uma versão mais antiga do .NET Core, provavelmente a execução dos dois exemplos será igualmente ruim. O .NET 6 atualizou a heurística do ThreadPool que reduz o impacto no desempenho do padrão de codificação ruim usado no primeiro exemplo.
Como detectar a privação do ThreadPool
Se você observar o comportamento acima em um serviço real, saberá que ele está respondendo lentamente sob carga, mas não saberá a causa. O dotnet-counters é uma ferramenta que mostra os contadores de desempenho em tempo real. Esses contadores podem dar pistas sobre certos problemas e costumam ser fáceis de obter. Em ambientes de produção, talvez você tenha contadores semelhantes fornecidos por ferramentas de monitoramento remoto e painéis da Web. Instale o dotnet-counters e comece a monitorar 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 demonstram um exemplo de quando o servidor Web não estava atendendo a nenhuma solicitação. Execute o Bombardier novamente com o ponto de extremidade api/diagscenario/tasksleepwait e uma carga sustentada por dois minutos, para que haja bastante tempo para observar o que acontece com os contadores de desempenho.
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/tasksleepwait -d 120s
A privação do ThreadPool ocorre quando não há threads livres para processar os itens de trabalho na fila e o runtime responde aumentando o número de threads do ThreadPool. Você deve observar o aumento rápido de ThreadPool Thread Count para duas a três vezes o número de núcleos de processador no computador e depois, a adição de mais threads, um a dois por segundo, até a estabilização final em um número acima de 125. O aumento lento e constante dos threads do ThreadPool combinados com o uso da CPU muito abaixo de 100% são os principais sinais de que a privação do ThreadPool é um gargalo de desempenho no momento. O aumento da contagem de threads continuará até que o pool atinja o número máximo de threads, que threads suficientes sejam criados para satisfazer todos os itens de trabalho de entrada ou que a CPU fique saturada. Muitas vezes, mas nem sempre, a privação do ThreadPool também mostra valores altos 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 sendo concluído. Veja um exemplo dos contadores enquanto a contagem de threads ainda está aumentando:
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
Depois que a contagem de threads do ThreadPool se estabilizar, não haverá mais privação no pool. Mas se ela se estabilizar com um valor alto (mais de três vezes o número de núcleos de processador), isso poderá indicar que o código do aplicativo está bloqueando alguns threads do ThreadPool e que o ThreadPool está compensando esse bloqueio com a execução de mais threads. A execução constante com altas contagens de threads não terá necessariamente um grande impacto na latência da solicitação, mas se a carga variar radicalmente ao longo do tempo ou se o aplicativo for reiniciado periodicamente, o ThreadPool poderá entrar em um período de privação aumentando lentamente os threads e prejudicando a latência da solicitação. Cada thread também consome memória, portanto, a redução do número total de threads necessários oferece outro benefício.
Do .NET 6 em diante, a heurística do ThreadPool foi modificada para escalar verticalmente o número de threads do ThreadPool com uma rapidez muito maior em resposta a determinadas APIs de Tarefa de bloqueio. A privação do ThreadPool ainda pode ocorrer com essas APIs, mas a duração é muito mais curta do que era nas versões mais antigas do .NET porque o runtime responde com mais rapidez. Execute o Bombardier novamente com o ponto de extremidade api/diagscenario/taskwait:
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s
No .NET 6, você vai observar que o pool aumenta a contagem de threads com mais rapidez do que antes e depois se estabiliza com um número alto de threads. A privação do ThreadPool ocorre enquanto a contagem de threads aumenta.
Como resolver a privação do ThreadPool
Para eliminar a privação do ThreadPool, os threads do ThreadPool precisam continuar desbloqueados e disponíveis para processar os itens de trabalho de entrada. Há duas maneiras de determinar o que cada thread estava fazendo, usando a ferramenta dotnet-stack ou capturando um despejo com dotnet-dump, que pode ser exibido no Visual Studio. O dotnet-stack pode ser mais rápido porque mostra as pilhas de thread imediatamente no console, mas a depuração de despejo do Visual Studio oferece melhores visualizações que mapeiam quadros para a origem, o recurso Apenas Meu Código pode filtrar quadros de implementação de runtime e o recurso Pilhas Paralelas pode ajudar a agrupar grandes números de threads com pilhas semelhantes. Este tutorial mostra a opção dotnet-stack. Confira o vídeo do tutorial de diagnóstico de privação do ThreadPool para obter um exemplo de investigação das pilhas de threads usando o Visual Studio.
Execute o Bombardier novamente para colocar uma carga no servidor Web:
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s
Depois, execute dotnet-stack para ver os rastreamentos da pilha de threads:
dotnet-stack report -n DiagnosticScenarios
Você verá uma saída longa contendo um grande número de pilhas, muitas das quais se parecem com esta:
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 quadros na parte inferior dessas pilhas indicam que esses threads são do ThreadPool:
System.Private.CoreLib.il!System.Threading.ThreadPoolWorkQueue.Dispatch()
System.Private.CoreLib.il!System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()
E os quadros próximos da parte superior revelam que o thread está bloqueado em uma chamada de GetResultCore(bool) 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 você pode navegar até o código desse controlador no arquivo Controllers/DiagnosticScenarios.cs do aplicativo de exemplo para ver que ele está chamando uma API assíncrona sem usar await. Esse é o padrão de código síncrono sobre assíncrono, que é conhecido por bloquear threads e é a causa mais comum de privação do ThreadPool.
public ActionResult<string> TaskWait()
{
// ...
Customer c = PretendQueryCustomerFromDbAsync("Dana").Result;
return "success:taskwait";
}
Nesse caso, o código pode ser alterado facilmente para usar o padrão assíncrono/espera, conforme é mostrado no ponto de extremidade TaskAsyncWait(). O uso da espera permite que o thread atual atenda a outros itens de trabalho enquanto a consulta de banco de dados está em andamento. Quando a pesquisa de banco de dados é concluída, um thread do ThreadPool retoma a execução. Dessa forma, nenhum thread é bloqueado no código durante cada solicitação:
public async Task<ActionResult<string>> TaskAsyncWait()
{
// ...
Customer c = await PretendQueryCustomerFromDbAsync("Dana");
return "success:taskasyncwait";
}
A execução do Bombadier para enviar carga ao ponto de extremidade api/diagscenario/taskasyncwait mostra que a contagem de threads do ThreadPool continua muito menor e a latência média continua perto de 500 ms quando a abordagem assíncrona/espera é usada:
>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
