Debug della mancanza di risorse di ThreadPool
Questo articolo si applica a: ✔️ .NET Core 3.1 e versioni successive
In questa esercitazione si apprenderà come eseguire il debug di uno scenario di starvation di ThreadPool. La starvation di ThreadPool si verifica quando il pool non dispone di thread disponibili per elaborare nuovi elementi di lavoro e spesso causa la risposta lenta delle applicazioni. Usando l'esempio fornito dall'app Web ASP.NET Core, è possibile causare la starvation di ThreadPool intenzionalmente e imparare a diagnosticarla.
Questa esercitazione illustra come:
- Analizzare un'app che risponde alle richieste lentamente
- Usare lo strumento dotnet-counters per identificare la probabile starvation di ThreadPool
- Usare lo strumento dotnet-stack per determinare il lavoro che mantiene impegnati i thread ThreadPool
Prerequisiti
L'esercitazione usa:
- SDK di .NET Core 6.0 per compilare ed eseguire l'app di esempio
- App Web di esempio per illustrare il comportamento di starvation di ThreadPool
- Bombardier per generare il carico per l'app Web di esempio
- dotnet-counters per osservare i contatori delle prestazioni
- dotnet-stack per esaminare gli stack di thread
Esecuzione dell'app di esempio
Scaricare il codice per l'app di esempio e compilarlo usando SDK di .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.26Eseguire l'app:
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 si usa un Web browser e si inviano richieste a https://localhost:5001/api/diagscenario/taskwait, verrà visualizzata la risposta success:taskwait restituita dopo circa 500 ms. Ciò mostra che il server Web gestisce il traffico come previsto.
Osservazione delle prestazioni lente
Il server Web demo include diversi endpoint che simulano l'invio di una richiesta di database e quindi la restituzione di una risposta all'utente. Ognuno di questi endpoint ha un ritardo di circa 500 ms durante la gestione delle richieste una alla volta, ma le prestazioni sono di gran lunga peggiori quando il server Web è soggetto a un determinato carico. Scaricare lo strumento di test di carico Bombardier e osservare la differenza di latenza quando vengono inviate 125 richieste simultanee a ogni endpoint.
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
Questo secondo endpoint usa un modello di codice che esegue anche peggio:
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
Entrambi gli endpoint mostrano significativamente più della latenza media di 500 ms quando il carico è elevato (rispettivamente 3,48 s e 15,42 s). Se si esegue questo esempio in una versione precedente di .NET Core, è probabile che entrambi gli esempi vengano eseguiti altrettanto male. .NET 6 ha aggiornato l'euristica di ThreadPool che riduce l'impatto sulle prestazioni del modello di codifica non valido usato nel primo esempio.
Rilevamento della starvation di ThreadPool
Se si osserva il comportamento precedente in un servizio reale, si comprende che risponde lentamente sotto carico, ma non si conosce la causa. dotnet-counters è uno strumento che può visualizzare i contatori delle prestazioni live. Tali contatori possono fornire indizi su determinati problemi e spesso sono facili da ottenere. Negli ambienti di produzione, si possono avere contatori simili forniti da strumenti di monitoraggio remoto e dashboard Web. Installare dotnet-counters e iniziare a monitorare il servizio 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
I contatori precedenti sono di esempio mentre il server Web non stava eseguendo alcuna richiesta. Eseguire nuovamente Bombardier con l'endpoint api/diagscenario/tasksleepwait e il carico sostenuto per 2 minuti, in modo che ci sia tempo per osservare cosa accade ai contatori delle prestazioni.
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/tasksleepwait -d 120s
La starvation di ThreadPool si verifica quando non sono presenti thread liberi per gestire gli elementi di lavoro in coda e il runtime risponde aumentando il numero di thread ThreadPool. Si deve osservare l'aumento rapido di ThreadPool Thread Count di 2-3 volte il numero di core del processore nel computer mentre altri thread vengono aggiunti 1-2 al secondo fino alla stabilizzazione in un punto superiore a 125. L'aumento lento e costante dei thread ThreadPool combinati con l'utilizzo della CPU molto inferiore al 100% sono i segnali chiave che la starvation di ThreadPool rappresenta al momento un collo di bottiglia delle prestazioni. L'aumento del numero di thread continuerà fino a quando il pool raggiunge il numero massimo di thread e sono stati creati thread sufficienti per soddisfare tutti gli elementi di lavoro in ingresso o la CPU è stata saturata. Spesso, ma non sempre, la starvation di ThreadPool mostrerà anche valori di grandi dimensioni per ThreadPool Queue Length e valori di ThreadPool Completed Work Item Count inferiori, ovvero c'è una grande quantità di lavoro in sospeso e poco lavoro da completare. Ecco un esempio dei contatori mentre il conteggio dei thread è ancora in aumento:
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
Una volta stabilizzato il numero di thread ThreadPool, il pool non è più in starving. Tuttavia, se si stabilizza a un valore elevato (più di tre volte il numero di core del processore), che in genere indica che il codice dell'applicazione blocca alcuni thread ThreadPool e ThreadPool viene compensato eseguendo con più thread. L'esecuzione costante a un numero elevato di thread non avrà necessariamente un impatto elevato sulla latenza delle richieste, ma se il carico varia notevolmente nel corso del tempo o l'app verrà riavviata periodicamente, ogni volta che ThreadPool entra in un periodo di starvation in cui aumenta lentamente i thread e offre una latenza di richiesta scarsa. Ogni thread utilizza inoltre memoria, quindi la riduzione del numero totale di thread necessari offre un altro vantaggio.
A partire da .NET 6, l'euristica di ThreadPool è stata modificata per aumentare il numero di thread di ThreadPool molto più velocemente in risposta a determinate API di attività di blocco. La starvation di ThreadPool può comunque verificarsi con tali API, ma la durata è molto più breve rispetto a quella delle versioni precedenti di .NET perché il runtime risponde più rapidamente. Eseguire di nuovo Bombardier con l'endpoint api/diagscenario/taskwait :
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s
In .NET 6, è necessario osservare che il pool aumenta il numero di thread più rapidamente di prima e quindi stabilizza in un numero elevato di thread. La starvation di ThreadPool si verifica mentre il conteggio dei thread scala.
Risoluzione della starvation di ThreadPool
Per eliminare la starvation di ThreadPool, i thread di ThreadPool devono rimanere sbloccati in modo che siano disponibili per gestire gli elementi di lavoro in ingresso. Esistono due modi per determinare le operazioni eseguite da ogni thread, usando lo strumento dotnet-stack o acquisendo un dump con dotnet-dump che può essere visualizzato in Visual Studio. dotnet-stack può essere più veloce poiché mostra immediatamente gli stack di thread nella console, ma il debug del dump di Visual Studio offre visualizzazioni migliori che eseguono il mapping dei fotogrammi all'origine, Just My Code può filtrare i frame di implementazione del runtime e la funzionalità Stack paralleli può aiutare a raggruppare un numero elevato di thread con stack simili. Questa esercitazione illustra l'opzione dotnet-stack. Per un esempio di analisi degli stack di thread con Visual Studio, vedere il video dell'esercitazione sulla diagnosi della fame di ThreadPool.
Eseguire di nuovo Bombardier per caricare il server Web:
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s
Eseguire quindi dotnet-stack per visualizzare le tracce dello stack di thread:
dotnet-stack report -n DiagnosticScenarios
Verrà visualizzato un output lungo contenente un numero elevato di stack, molti dei quali hanno un aspetto simile al seguente:
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()
I frame nella parte inferiore di tali stack indicano che questi thread sono thread di ThreadPool:
System.Private.CoreLib.il!System.Threading.ThreadPoolWorkQueue.Dispatch()
System.Private.CoreLib.il!System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()
I fotogrammi nella parte superiore rivelano che il thread è bloccato in una chiamata a GetResultCore(bool) dalla funzione 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()
È ora possibile passare al codice per questo controller nel file controller/DiagnosticScenarios.cs dell'app di esempio per vedere che sta chiamando un'API asincrona senza usare await. Si tratta del modello di codice sync-over-async, noto per bloccare i thread ed è la causa più comune della fame di ThreadPool.
public ActionResult<string> TaskWait()
{
// ...
Customer c = PretendQueryCustomerFromDbAsync("Dana").Result;
return "success:taskwait";
}
In questo caso, il codice può essere facilmente modificato per usare Async/Await, come illustrato nell'endpoint TaskAsyncWait(). L'uso di Await consente al thread corrente di gestire altri elementi di lavoro mentre la query di database è in corso. Al termine della ricerca del database, un thread di ThreadPool riprenderà l'esecuzione. In questo modo non viene bloccato alcun thread nel codice durante ogni richiesta:
public async Task<ActionResult<string>> TaskAsyncWait()
{
// ...
Customer c = await PretendQueryCustomerFromDbAsync("Dana");
return "success:taskasyncwait";
}
L'esecuzione di Bombadier per inviare il carico all'endpoint api/diagscenario/taskasyncwait indica che il numero di thread di ThreadPool rimane molto inferiore e la latenza media rimane vicina a 500 ms quando si usa l'approccio Async/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
