Compartilhar via


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:

Executando o aplicativo de exemplo

  1. 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.26
    
  2. Executar 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