偵錯 ThreadPool 耗盡
本文適用於:✔️ .NET Core 3.1 與更新版本
在本教學課程中,您將了解如何對 ThreadPool 耗盡情節進行偵錯。 如果集區沒有可用的執行緒來處理新的工作項目,而且通常會導致應用程式回應緩慢,則會發生 ThreadPool 耗盡。 使用提供的範例 ASP.NET Core Web 應用程式,您可以刻意造成 ThreadPool 耗盡,並了解如何進行診斷。
在此教學課程中,您需要:
- 調查緩慢回應要求的應用程式
- 使用 dotnet-counters 工具來識別 ThreadPool 耗盡可能發生
- 使用 dotnet-stack 工具來判斷哪些工作讓 ThreadPool 執行緒保持忙碌
必要條件
教學課程使用:
- 建置和執行範例應用程式的 .NET Core 6.0 SDK
- 示範 ThreadPool 耗盡行為的範例 Web 應用程式
- 產生範例 Web 應用程式負載的 Bombardier
- 觀察效能計數器的 dotnet-counters
- 檢查執行緒堆疊的 dotnet-stack
執行範例應用程式
下載範例應用程式的程式碼,並使用 .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.26
執行應用程式:
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
如果您使用網頁瀏覽器,並將要求傳送至 https://localhost:5001/api/diagscenario/taskwait
,則應該會在大約 500 毫秒之後看到所傳回的回應 success:taskwait
。 這會顯示網路伺服器正在如預期般提供流量。
觀察緩慢效能
示範網路伺服器有數個端點可模擬執行資料庫要求,然後將回應傳回給使用者。 所有這些端點在一次提供一個要求時會有大約 500 毫秒的延遲,但在網路伺服器受限於某些負載時,效能會更差。 下載 Bombardier 負載測試工具,並觀察到將 125 個並行要求傳送至每個端點時的延遲差異。
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
這個第二個端點會使用執行效能更差的程式碼模式:
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
負載高時,這兩個端點會顯示明顯超過 500 毫秒的平均延遲 (分別為 3.48 秒和 15.42 秒)。 如果您在舊版 .NET Core 上執行此範例,則可能會看到這兩個範例執行效能一樣地差。 .NET 6 已更新 ThreadPool 啟發學習法,以減少第一個範例中所使用錯誤程式碼模式的效能影響。
偵錯 ThreadPool 耗盡
如果您在真實世界服務上觀察到上述行為,則會知道低於負載而回應緩慢,但您不知道原因。 dotnet-counters 是可顯示即時效能計數器的工具。 這些計數器可以提供特定問題的線索,而且通常很容易取得。 在實際執行環境中,您可能會有遠端監視工具和 Web 儀表板所提供的類似計數器。 安裝 dotnet-counters,並開始監視 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
上述計數器是網路伺服器未提供任何要求時的範例。 使用 api/diagscenario/tasksleepwait
端點再次執行 Bombardier,並持續負載 2 分鐘,因此有足夠的時間觀察效能計數器發生什麼情況。
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/tasksleepwait -d 120s
如果沒有任何可用的執行緒來處理已排入佇列的工作項目,而且執行階段以增加 ThreadPool 執行緒數目來回應,則會發生 ThreadPool 耗盡。 您應該觀察到 ThreadPool Thread Count
快速增加到機器上處理器核心數目的 2-3 倍,甚至每秒會新增 1-2 個執行緒,直到某個位置最終穩定超過 125 個。 與遠小於 100% 的 CPU 使用量合併使用的 ThreadPool 執行緒速度緩慢且穩定增加,是 ThreadPool 耗盡目前是效能瓶頸的關鍵訊號。 除非集區達到執行緒數目上限、所建立的執行緒足以滿足所有傳入工作項目,或 CPU 已飽和,否則將會繼續增加執行緒計數。 通常,但並非一定,ThreadPool 耗盡也會顯示 ThreadPool Queue Length
的較大值和 ThreadPool Completed Work Item Count
的最低值,這表示有大量的擱置工作和少量工作正在完成。 以下是執行緒計數仍在增加時的計數器範例:
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
ThreadPool 執行緒計數穩定之後,集區就不會再耗盡。 但是,如果以較高的值穩定 (超過處理器核心數目的三倍),則這通常指出應用程式碼要封鎖某些 ThreadPool 執行緒,而 ThreadPool 會使用更多的執行緒來執行以進行補償。 以高執行緒計數上穩定執行,不一定會對要求延遲造成很大的影響,但如果負載隨著時間而大幅變化,或定期重新啟動應用程式,則每次 ThreadPool 可能會進入一段時間的耗盡,其中執行緒會緩慢增加,並提供不正確的要求延遲。 每個執行緒也會耗用記憶體,因此減少所需的執行緒總數可提供另一個優點。
從 .NET 6 開始,已修改 ThreadPool 啟發學習法,以更快速地擴大 ThreadPool 執行緒數目,來回應特定封鎖工作 API。 這些 API 仍然可以發生 ThreadPool 耗盡,但持續期間會比 .NET 舊版本更為簡短,因為執行階段回應更為快速。 使用 api/diagscenario/taskwait
端點再次執行 Bombardier:
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s
在 .NET 6 上,您應該會觀察到集區的執行緒計數增加速度比之前還要快,然後在大量執行緒時穩定。 執行緒計數增加時發生 ThreadPool 耗盡。
解決 ThreadPool 耗盡
若要消除 ThreadPool 耗盡,ThreadPool 執行緒需要保持解除封鎖狀態,才能處理傳入工作項目。 不論是使用 dotnet-stack 工具,還是使用可在 Visual Studio 中檢視的 dotnet-dump 來擷取傾印,都有兩種方式可以判斷每個執行緒的用途。 dotnet-stack 可能比較快,因為會在主控台上立即顯示執行緒堆疊,但 Visual Studio 傾印偵錯提供可將框架對應至來源的較佳視覺效果、Just My Code 可以篩選出執行階段實作框架,而平行堆疊功能可以協助分組具有類似堆疊的大量執行緒。 本教學課程顯示 dotnet-stack 選項。 如需使用 Visual Studio 調查執行緒堆疊的範例,請參閱診斷 ThreadPool 耗盡教學課程影片。
再次執行 Bombardier,讓網路伺服器低於負載:
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s
然後執行 dotnet-stack 以查看執行緒堆疊追蹤:
dotnet-stack report -n DiagnosticScenarios
您應該會看到包含大量堆疊的詳細輸出,其中有許多看起來像這樣:
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()
這些堆疊底部的框架指出這些執行緒是 ThreadPool 執行緒:
System.Private.CoreLib.il!System.Threading.ThreadPoolWorkQueue.Dispatch()
System.Private.CoreLib.il!System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()
而接近最上層的框架會顯示執行緒在從 DiagnosticScenarioController.TaskWait() 函數呼叫 GetResultCore(bool)
時遭到封鎖:
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()
現在,您可以在範例應用程式的 Controllers/DiagnosticScenarios.cs 檔案中導覽至此控制器的程式碼,以查看其正在呼叫非同步 API,而不使用 await
。 這是非同步中的同步程式碼模式,這已知會封鎖執行緒,而且是 ThreadPool 耗盡最常見的原因。
public ActionResult<string> TaskWait()
{
// ...
Customer c = PretendQueryCustomerFromDbAsync("Dana").Result;
return "success:taskwait";
}
在此情況下,程式碼可以立即變更為改用 async/await,如 TaskAsyncWait()
端點所示。 使用 await 可讓目前執行緒在資料庫查詢進行時服務其他工作項目。 資料庫查閱完成時,ThreadPool 執行緒將會繼續執行。 如此一來,在每個要求期間,程式碼中不會封鎖任何執行緒:
public async Task<ActionResult<string>> TaskAsyncWait()
{
// ...
Customer c = await PretendQueryCustomerFromDbAsync("Dana");
return "success:taskasyncwait";
}
執行 Bombadier 以將負載傳送至 api/diagscenario/taskasyncwait
端點時會顯示在使用 async/await 方法時,ThreadPool 執行緒計數會較少,而且平均延遲會維持接近 500 毫秒:
>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