Déboguer la privation de ThreadPool

Article
06/05/2023

Cet article s’applique à : ✔️ .NET Core 3.1 et versions ultérieures

Dans ce tutoriel, vous allez apprendre à déboguer un scénario de privation de ThreadPool. La privation de ThreadPool se produit lorsque le pool n’a pas de threads disponibles pour traiter de nouveaux éléments de travail et entraîne souvent une réponse lente des applications. À l’aide de l’exemple d’application web ASP.NET Core fourni, vous pouvez provoquer intentionnellement une privation de ThreadPool et apprendre à le diagnostiquer.

Ce didacticiel présente les procédures suivantes :

Examiner une application qui répond lentement aux demandes
Utiliser l’outil dotnet-counters pour identifier qu’il s’agit sûrement d’une privation de ThreadPool
Utiliser l’outil dotnet-stack pour déterminer le travail qui maintient les threads ThreadPool occupés

Prérequis

Le didacticiel utilise :

Kit de développement logiciel (SDK) .NET Core 6.0 pour générer et exécuter l’exemple d’application
Exemple d’application web pour illustrer le comportement de la privation de ThreadPool
Bombardier génère la charge pour l’exemple d’application web
dotnet-counters pour observer les compteurs de performances
dotnet-stack pour examiner les piles de threads

Exécution de l’exemple d’application

Téléchargez le code de l’exemple d’application et générez-le à l’aide du 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

Exécutez l’application :

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

Si vous utilisez un navigateur web et envoyez des requêtes à https://localhost:5001/api/diagscenario/taskwait, vous devriez voir la réponse success:taskwait retournée après environ 500 ms. Cela montre que le serveur web traite le trafic comme prévu.

Observation de performances lentes

Le serveur web de démonstration a plusieurs points de terminaison qui imite une demande de base de données, puis le renvoi d’une réponse à l’utilisateur. Chacun de ces points de terminaison a un délai d’environ 500 ms lors du traitement des requêtes une par une, mais les performances sont bien pires lorsque le serveur web est soumis à une certaine charge. Téléchargez l’outil de test de charge Bombardier et observez la différence de latence lorsque 125 demandes simultanées sont envoyées à chaque point de terminaison.

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

Ce deuxième point de terminaison utilise un modèle de code qui fonctionne encore moins bien :

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

Ces deux points de terminaison affichent une latence considérablement supérieure à la latence moyenne de 500 ms lorsque la charge est élevée (respectivement 3,48 s et 15,42 s). Si vous exécutez cet exemple sur une version antérieure de .NET Core, il est probable que les deux exemples fonctionnent aussi mal. .NET 6 a mis à jour l’heuristique de ThreadPool qui réduit l’impact sur les performances du modèle de codage incorrect utilisé dans le premier exemple.

Détecter la privation de ThreadPool

Si vous avez observé le comportement ci-dessus sur un service réel, vous savez qu’il répond lentement sous la charge, mais vous n’en connaissez pas la cause. dotnet-counters est un outil qui peut afficher des compteurs de performances en direct. Ces compteurs peuvent fournir des indices sur certains problèmes et sont souvent faciles à obtenir. Dans les environnements de production, vous pouvez avoir des compteurs similaires fournis par les outils de monitoring à distance et les tableaux de bord web. Installez dotnet-counters et commencez à surveiller le service 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

Les compteurs ci-dessus sont un exemple alors que le serveur web ne servait aucune requête. Réexécutez Bombardier avec le point de terminaison api/diagscenario/tasksleepwait et une charge soutenue pendant 2 minutes afin d’observer ce qui arrive aux compteurs de performance.

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

La privation de ThreadPool se produit lorsqu’il n’y a pas de threads libres pour gérer les éléments de travail mis en file d’attente et que le runtime répond en augmentant le nombre de threads ThreadPool. Vous devez observer l’augmentation rapide de ThreadPool Thread Count à 2-3 fois le nombre de cœurs de processeur sur votre machine, puis d’autres threads sont ajoutés de 1 à 2 par seconde jusqu’à se stabiliser finalement quelque part au-dessus de 125. L’augmentation lente et régulière des threads ThreadPool combinée à une utilisation du processeur bien inférieure à 100 % sont les principaux indicateurs que la privation de ThreadPool est actuellement la cause de la baisse des performances. L’augmentation du nombre de threads se poursuit jusqu’à ce que le pool atteigne le nombre maximal de threads, que suffisamment de threads aient été créés pour satisfaire tous les éléments de travail entrants ou que le processeur ait été saturé. Souvent, mais pas toujours, la privation de ThreadPool affiche également des valeurs importantes pour ThreadPool Queue Length et des valeurs faibles pour ThreadPool Completed Work Item Count, ce qui signifie qu’il y a une grande quantité de travail en attente et peu de travail en cours d’exécution. Voici un exemple de compteurs alors que le nombre de threads augmente toujours :

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

Une fois que le nombre de threads ThreadPool se stabilise, il n’y a plus de privation dans le pool. Mais s’il se stabilise à une valeur élevée (plus de trois fois le nombre de cœurs de processeur), cela indique généralement que le code de l’application bloque certains threads ThreadPool et que ThreadPool compense en s’exécutant avec plus de threads. L’exécution stable à un nombre élevé de threads n’aura pas nécessairement d’impact important sur la latence des demandes, mais si la charge varie considérablement au fil du temps ou si l’application est redémarrée périodiquement, le ThreadPool est susceptible d’entrer dans une période de privation pendant laquelle il augmente lentement les threads et fournit une latence de requête médiocre. Chaque thread consomme également de la mémoire. La réduction du nombre total de threads nécessaires offre donc un autre avantage.

À partir de .NET 6, l’heuristique de ThreadPool a été modifiée pour augmenter le nombre de threads ThreadPool beaucoup plus rapidement en réponse à certaines API de tâche bloquantes. La privation de ThreadPool peut toujours se produire avec ces API, mais la durée est beaucoup plus courte qu’avec les anciennes versions de .NET, car le runtime réagit plus rapidement. Réexécutez Bombardier avec le point de terminaison api/diagscenario/taskwait :

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

Sur .NET 6, vous devriez observer que le pool augmente le nombre de threads plus rapidement qu’auparavant, puis se stabilise à un nombre élevé de threads. La privation de ThreadPool se produit pendant que le nombre de threads augmente.

Résoudre la privation de ThreadPool

Pour éliminer la privation de ThreadPool, les threads ThreadPool doivent rester débloqués afin d’être disponibles pour gérer les éléments de travail entrants. Il existe deux façons de déterminer ce que chaque thread faisait, soit à l’aide de l’outil dotnet-stack, soit en capturant une image mémoire avec dotnet-dump, qui peut être visualisée dans Visual Studio. La méthode avec dotnet-stack peut être plus rapide, car elle affiche les piles de threads immédiatement sur la console, mais le débogage avec image mémoire dans Visual Studio offre de meilleures visualisations qui mappent les trames à la source. La fonctionnalité Uniquement mon code permet de filtrer les trames d’implémentation du runtime et la fonctionnalité Piles parallèles permet de regrouper un grand nombre de threads avec des piles similaires. Ce tutoriel montre l’option dotnet-stack. Pour obtenir un exemple d’examen des piles de threads à l’aide de Visual Studio, consultez la vidéo tutorielle sur le diagnostic de la privation de ThreadPool.

Réexécutez Bombardier pour mettre le serveur web sous charge :

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

Ensuite, exécutez dotnet-stack pour voir les arborescences des appels de procédure des threads :

dotnet-stack report -n DiagnosticScenarios

Vous devriez obtenir un grand résultat contenant un grand nombre de piles, dont la plupart ressemblent à ceci :

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()

Les trames situées au bas de ces piles indiquent que ces threads sont des threads ThreadPool :

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

Les images situées en haut révèlent que le thread est bloqué lors d’un appel à GetResultCore(bool) depuis la fonction 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()

Vous pouvez maintenant accéder au code de ce contrôleur dans le fichier Controllers/DiagnosticScenarios.cs de l’exemple d’application pour voir qu’il appelle une API asynchrone sans utiliser await. Il s’agit du modèle de code sync-over-async, qui est connu pour bloquer les threads et est la cause la plus courante de la privation de ThreadPool.

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

Dans ce cas, le code peut être facilement modifié pour utiliser la fonction async/await à la place, comme indiqué dans le point de terminaison TaskAsyncWait(). L’utilisation de la fonction await permet au thread actuel de traiter d’autres éléments de travail pendant que la requête de base de données est en cours. Une fois la recherche dans la base de données terminée, un thread ThreadPool reprend l’exécution. De cette façon, aucun thread n’est bloqué dans le code pendant chaque requête :

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

L’exécution de Bombardier pour envoyer la charge au point de terminaison api/diagscenario/taskasyncwait montre que le nombre de threads ThreadPool reste beaucoup plus faible et que la latence moyenne reste proche de 500 ms lors de l’utilisation de l’approche asynchrone/await :

>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

Partager via