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
Web ブラウザーを使って https://localhost:5001/api/diagscenario/taskwait に要求を送信すると、約 500 ms 後に success:taskwait という応答が返されます。 これは、Web サーバーが期待どおりにトラフィックを処理していることを示しています。
パフォーマンスの低下の観察
デモ Web サーバーには、データベース要求を実行して、ユーザーに応答を返すことを模倣するエンドポイントがいくつかあります。 これらの各エンドポイントは、一度に 1 つずつ要求を処理する場合、約 500 ms の遅延が発生しますが、Web サーバーに何らかの負荷がかかると、パフォーマンスが大幅に低下します。 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
この 2 つ目のエンドポイントでは、さらにパフォーマンスが低下するコード パターンを使っています。
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 ms の平均待機時間を大幅に超えます (それぞれ 3.48 s と 15.42 s)。 この例を以前のバージョンの .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
上のカウンターは、Web サーバーが要求を処理していないときの例です。 api/diagscenario/tasksleepwait エンドポイントで Bombardier をもう一度実行し、パフォーマンス カウンターで起こることを観察するのに十分な時間を確保するために、負荷の状態を 2 分間維持します。
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/tasksleepwait -d 120s
ThreadPool の枯渇は、キューに格納された作業項目を処理できる空きスレッドがないときに発生し、ランタイムでは ThreadPool のスレッド数を増やすことで対応します。 ThreadPool Thread Count がマシンのプロセッサ コア数の 2、3 倍に急速に増加し、最終的に 125 個を超えるどこかの時点で安定するまでスレッドが毎秒 1、2 個さらに追加されることを確認します。 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 のスレッド数が安定すると、プールは枯渇状態ではなくなります。 ただし、高い値 (プロセッサ コア数の約 3 倍超) で安定した場合、通常、アプリケーション コードが一部の ThreadPool スレッドをブロックし、ThreadPool がスレッド数を増やして実行することにより補っていることを示しています。 高いスレッド数で安定して動作している場合でも、要求の待機時間に大きな影響を及ぼすとは限りません。ただし、負荷が時間と共に大きく変化したり、アプリが定期的に再起動したりする場合、そのたびに ThreadPool が枯渇状態になり、スレッド数が徐々に増え、要求の待機時間が長くなる可能性があります。 各スレッドはメモリも消費するため、必要なスレッドの合計数を減らすことで、別の利点が得られます。
.NET 6 以降、ThreadPool のヒューリスティックは、特定のブロックするタスク API に応答して ThreadPool スレッド数をより高速にスケールアップするように変更されました。 これらの 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 のスレッドがブロックされないようにして、入ってくる作業項目を処理できるようにする必要があります。 各スレッドの実行内容を確認するには、2 つの方法があります。dotnet-stack ツールを使うか、Visual Studioで表示できるダンプを dotnet-dump を使ってキャプチャします。 スレッド スタックがコンソールに即座に表示されるので、dotnet-stack の方が高速な可能性があります。ただし、Visual Studio のダンプ デバッグには、フレームをソースにマップする優れた視覚化機能があり、[マイ コードのみ] にはランタイム実装フレームを絞り込む機能があり、Parallel Stacks 機能は同様のスタックがある多数のスレッドをグループ化するために役立ちます。 このチュートリアルでは、dotnet-stack オプションを紹介します。 Visual Studio を使ってスレッド スタックを調査する例については、ThreadPool の枯渇の診断に関するチュートリアル ビデオをご覧ください。
Bombardier をもう一度実行して、Web サーバーに負荷をかけます。
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 ファイルにあるこのコントローラーのコードに移動し、await を使わずに非同期 API を呼び出していることを確認できるようになりました。 これは sync-over-async コード パターンです。これによってスレッドがブロックされることがわかっており、ThreadPool の枯渇の最も一般的な原因です。
public ActionResult<string> TaskWait()
{
// ...
Customer c = PretendQueryCustomerFromDbAsync("Dana").Result;
return "success:taskwait";
}
この場合、TaskAsyncWait() エンドポイントに示すように、代わりに async/await を使用するようにコードを簡単に変更できます。 await を使用すると、データベース クエリの進行中に、現在のスレッドから他の作業項目にサービスを提供することができます。 データベース検索が完了すると、ThreadPool スレッドによって実行が再開されます。 これにより、各要求時にコード内でスレッドがブロックされることはありません。
public async Task<ActionResult<string>> TaskAsyncWait()
{
// ...
Customer c = await PretendQueryCustomerFromDbAsync("Dana");
return "success:taskasyncwait";
}
api/diagscenario/taskasyncwait エンドポイントに読み込みを送信するために Bombadier を実行した場合、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
.NET
フィードバック
以下は間もなく提供いたします。2024 年を通じて、コンテンツのフィードバック メカニズムとして GitHub の issue を段階的に廃止し、新しいフィードバック システムに置き換えます。 詳細については、「https://aka.ms/ContentUserFeedback」を参照してください。
フィードバックの送信と表示