Fouten opsporen in ThreadPool Starvation
Dit artikel is van toepassing op: ✔️ .NET Core 3.1 en latere versies
In deze zelfstudie leert u hoe u fouten in een ThreadPool-starvation-scenario kunt opsporen. ThreadPool-starvatie treedt op wanneer de pool geen beschikbare threads heeft om nieuwe werkitems te verwerken en dit er vaak voor zorgt dat toepassingen langzaam reageren. Aan de hand van het opgegeven voorbeeld ASP.NET Core web-app kunt u threadPool-starvatie opzettelijk veroorzaken en leren hoe u deze kunt diagnosticeren.
In deze zelfstudie leert u het volgende:
- Een app onderzoeken die langzaam op aanvragen reageert
- Gebruik het hulpprogramma dotnet-tellers om threadpool-starvation te identificeren die waarschijnlijk optreedt
- Gebruik het hulpprogramma dotnet-stack om te bepalen welk werk de ThreadPool-threads bezet houdt
Vereisten
In de zelfstudie wordt het volgende gebruikt:
- .NET Core 6.0 SDK voor het bouwen en uitvoeren van de voorbeeld-app
- Voorbeeld van een web-app om het gedrag van ThreadPool-verhongering aan te tonen
- Bombardier voor het genereren van belasting voor de voorbeeldweb-app
- dotnet-tellers om prestatiemeteritems te observeren
- dotnet-stack om threadstacks te onderzoeken
De voorbeeld-app uitvoeren
Download de code voor de voorbeeld-app en bouw deze met behulp van de .NET SDK:
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.26De app uitvoeren:
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
Als u een webbrowser gebruikt en aanvragen verzendt naar https://localhost:5001/api/diagscenario/taskwait, ziet u dat het antwoord success:taskwait na ongeveer 500 ms wordt geretourneerd. Dit geeft aan dat de webserver verkeer afhandelt zoals verwacht.
Trage prestaties observeren
De demowebserver heeft verschillende eindpunten die een databaseaanvraag nabootsen en vervolgens een antwoord aan de gebruiker retourneren. Elk van deze eindpunten heeft een vertraging van ongeveer 500 ms wanneer aanvragen één voor één worden verwerkt, maar de prestaties zijn veel slechter wanneer de webserver wordt belast. Download het hulpprogramma Voor het testen van de belasting van Bombardier en bekijk het verschil in latentie wanneer er 125 gelijktijdige aanvragen naar elk eindpunt worden verzonden.
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
Dit tweede eindpunt maakt gebruik van een codepatroon dat nog slechter presteert:
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
Beide eindpunten tonen aanzienlijk meer dan de gemiddelde latentie van 500 ms wanneer de belasting hoog is (respectievelijk 3,48 s en 15,42 s). Als u dit voorbeeld uitvoert op een oudere versie van .NET Core, zult u waarschijnlijk zien dat beide voorbeelden even slecht presteren. .NET 6 heeft threadpool-heuristieken bijgewerkt die de impact op de prestaties verminderen van het slechte coderingspatroon dat in het eerste voorbeeld wordt gebruikt.
ThreadPool-starvatie detecteren
Als u het bovenstaande gedrag in een echte service zou observeren, zou u weten dat deze langzaam reageert onder belasting, maar u weet niet wat de oorzaak is. dotnet-counters is een hulpprogramma waarmee live prestatiemeteritems kunnen worden weergegeven. Deze tellers kunnen aanwijzingen geven over bepaalde problemen en zijn vaak gemakkelijk te verkrijgen. In productieomgevingen hebt u mogelijk vergelijkbare tellers die worden geleverd door externe bewakingshulpprogramma's en webdashboards. Installeer dotnet-tellers en begin met het bewaken van de webservice:
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
De bovenstaande tellers zijn een voorbeeld terwijl de webserver geen aanvragen afhandelde. Voer Bombardier opnieuw uit met het api/diagscenario/tasksleepwait eindpunt en heeft de belasting gedurende 2 minuten volgehouden, zodat er voldoende tijd is om te kijken wat er met de prestatiemeteritems gebeurt.
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/tasksleepwait -d 120s
ThreadPool-starvatie treedt op wanneer er geen gratis threads zijn om de werkitems in de wachtrij te verwerken en de runtime reageert door het aantal ThreadPool-threads te verhogen. U moet de snelle toename tot 2-3x het aantal processorkernen op uw computer observeren ThreadPool Thread Count en vervolgens worden verdere threads 1-2 per seconde toegevoegd totdat ze uiteindelijk ergens boven 125 stabiliseren. De trage en gestage toename van ThreadPool-threads in combinatie met het CPU-gebruik veel minder dan 100% zijn de belangrijkste signalen dat ThreadPool-starvatie momenteel een prestatieknelpunt is. De toename van het aantal threads gaat door totdat de pool het maximum aantal threads bereikt, er voldoende threads zijn gemaakt om te voldoen aan alle binnenkomende werkitems of de CPU is verzadigd. Vaak, maar niet altijd, toont ThreadPool-verhongering ook grote waarden voor ThreadPool Queue Length en lage waarden voor ThreadPool Completed Work Item Count, wat betekent dat er een grote hoeveelheid werk in behandeling is en er weinig werk wordt voltooid. Hier volgt een voorbeeld van de tellers terwijl het aantal threads nog steeds toeneemt:
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
Zodra het aantal ThreadPool-threads is gestabiliseerd, krijgt de pool geen honger meer. Maar als het zich stabiliseert bij een hoge waarde (meer dan ongeveer drie keer het aantal processorkernen), betekent dit meestal dat de toepassingscode sommige ThreadPool-threads blokkeert en de ThreadPool compenseert door uit te voeren met meer threads. Bij een hoog aantal threads heeft dit niet noodzakelijkerwijs grote gevolgen voor de latentie van aanvragen, maar als de belasting in de loop van de tijd aanzienlijk varieert of als de app periodiek opnieuw wordt gestart, zal de ThreadPool waarschijnlijk elke keer een periode van uithongering ingaan, waarbij de threads langzaam toenemen en een slechte aanvraaglatentie oplevert. Elke thread verbruikt ook geheugen, dus het verminderen van het totale aantal benodigde threads biedt nog een voordeel.
Vanaf .NET 6 zijn de threadpool-heuristieken gewijzigd om het aantal ThreadPool-threads veel sneller op te schalen als reactie op bepaalde blokkerende taak-API's. ThreadPool-starvatie kan nog steeds optreden met deze API's, maar de duur is veel korter dan bij oudere .NET-versies omdat de runtime sneller reageert. Voer Bombardier opnieuw uit met het api/diagscenario/taskwait eindpunt:
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s
Op .NET 6 moet u zien dat de pool het aantal threads sneller verhoogt dan voorheen en zich vervolgens stabiliseren bij een groot aantal threads. ThreadPool-verhongering treedt op terwijl het aantal threads stijgt.
ThreadPool-starvatie oplossen
Als u ThreadPool-starvatie wilt elimineren, moeten ThreadPool-threads gedeblokkeerd blijven, zodat ze beschikbaar zijn voor het afhandelen van binnenkomende werkitems. Er zijn twee manieren om te bepalen wat elke thread deed, met behulp van het hulpprogramma dotnet-stack of het vastleggen van een dump met dotnet-dump die kan worden weergegeven in Visual Studio. dotnet-stack kan sneller zijn omdat de threadstacks direct op de console worden weergegeven, maar Visual Studio-dumpfoutopsporing biedt betere visualisaties die frames toewijzen aan de bron, Just My Code kan runtime-implementatieframes filteren en de functie Parallel Stacks kan helpen bij het groeperen van grote aantallen threads met vergelijkbare stacks. In deze zelfstudie wordt de dotnet-stack-optie weergegeven. Zie de zelfstudievideo over het diagnosticeren van ThreadPool-starvation voor een voorbeeld van het onderzoeken van de threadstacks met behulp van Visual Studio.
Voer Bombardier opnieuw uit om de webserver onder belasting te plaatsen:
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s
Voer vervolgens dotnet-stack uit om de threadstacktraceringen te bekijken:
dotnet-stack report -n DiagnosticScenarios
Als het goed is, ziet u een lange uitvoer met een groot aantal stacks, waarvan vele er als volgt uitzien:
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()
De frames onder aan deze stacks geven aan dat deze threads ThreadPool-threads zijn:
System.Private.CoreLib.il!System.Threading.ThreadPoolWorkQueue.Dispatch()
System.Private.CoreLib.il!System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()
En de frames bovenaan laten zien dat de thread is geblokkeerd bij een aanroep van GetResultCore(bool) de functie 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()
U kunt nu naar de code voor deze controller navigeren in het bestand Controllers/DiagnosticScenarios.cs van de voorbeeld-app om te zien dat er een asynchrone API wordt aangeroepen zonder gebruik te maken van await. Dit is het synchronisatie-over-asynchrone codepatroon, waarvan bekend is dat threads worden geblokkeerd en dat de meest voorkomende oorzaak van ThreadPool-starvatie is.
public ActionResult<string> TaskWait()
{
// ...
Customer c = PretendQueryCustomerFromDbAsync("Dana").Result;
return "success:taskwait";
}
In dit geval kan de code gemakkelijk worden gewijzigd om in plaats daarvan de async/await te gebruiken, zoals wordt weergegeven in het TaskAsyncWait() eindpunt. Als u await gebruikt, kan de huidige thread andere werkitems onderhouden terwijl de databasequery wordt uitgevoerd. Wanneer het opzoeken van de database is voltooid, wordt de uitvoering van een ThreadPool-thread hervat. Op deze manier wordt er geen thread geblokkeerd in de code tijdens elke aanvraag:
public async Task<ActionResult<string>> TaskAsyncWait()
{
// ...
Customer c = await PretendQueryCustomerFromDbAsync("Dana");
return "success:taskasyncwait";
}
Als u Bombadier uitvoert om belasting naar het api/diagscenario/taskasyncwait eindpunt te verzenden, ziet u dat het aantal ThreadPool-threads veel lager blijft en dat de gemiddelde latentie bijna 500 ms blijft bij het gebruik van de async/await-benadering:
>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
Feedback
Binnenkort beschikbaar: In de loop van 2024 zullen we GitHub-problemen geleidelijk uitfaseren als het feedbackmechanisme voor inhoud en deze vervangen door een nieuw feedbacksysteem. Zie voor meer informatie: https://aka.ms/ContentUserFeedback.
Feedback verzenden en weergeven voor