Отладка threadPool Starvation
Эта статья относится к: ✔️ .NET Core 3.1 и более поздних версий
В этом руководстве описано, как выполнить отладку сценария нехватки ThreadPool. Нехватка ThreadPool возникает, когда в пуле нет доступных потоков для обработки новых рабочих элементов, и это часто приводит к медленному реагированию приложений. Используя предоставленный пример ASP.NET Core веб-приложении, вы можете намеренно вызвать нехватку ThreadPool и узнать, как его диагностировать.
Выполняя данное руководство, вы сделаете следующее:
- Изучение приложения, которое медленно отвечает на запросы
- Использование средства dotnet-counters для определения вероятного возникновения нехватки ThreadPool
- Используйте средство dotnet-stack, чтобы определить, какая работа сохраняет потоки ThreadPool занятыми.
Предварительные требования
В этом учебнике используется:
- Пакет SDK для .NET Core 6.0 для сборки и запуска примера приложения
- Пример веб-приложения для демонстрации поведения при нехватке ThreadPool
- Bombardier для создания нагрузки для примера веб-приложения
- dotnet-counters для наблюдения за счетчиками производительности
- dotnet-stack для проверки стеков потоков
Выполнение примера приложения
Скачайте код для примера приложения и выполните его сборку с помощью пакета 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Запустите приложение:
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, вы увидите ответ success:taskwait , возвращенный примерно через 500 мс. Это показывает, что веб-сервер обслуживает трафик должным образом.
Наблюдение за низкой производительностью
Демонстрационный веб-сервер имеет несколько конечных точек, которые имитирует выполнение запроса базы данных, а затем возвращает ответ пользователю. Каждая из этих конечных точек имеет задержку примерно в 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 — это средство, которое может отображать динамические счетчики производительности. Эти счетчики могут дать подсказки о некоторых проблемах и часто легко получить. В рабочих средах могут быть аналогичные счетчики, предоставляемые средствами удаленного мониторинга и веб-панелями мониторинга. Установите dotnet-counters и начните мониторинг веб-службы:
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
Приведенные выше счетчики являются примером, в то время как веб-сервер не обслуживал запросы. Снова запустите Bombardier с конечной api/diagscenario/tasksleepwait точкой и постоянной нагрузкой в течение 2 минут, чтобы было достаточно времени, чтобы понаблюдать за тем, что происходит со счетчиками производительности.
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/tasksleepwait -d 120s
Нехватка ThreadPool возникает, когда отсутствуют свободные потоки для обработки рабочих элементов, помещенных в очередь, и среда выполнения реагирует увеличением числа потоков ThreadPool. Вы должны наблюдать ThreadPool Thread Count быстрое увеличение числа ядер процессора на компьютере в 2–3 раз, а затем последующие потоки добавляются 1–2 в секунду, пока в конечном итоге не стабилизируется где-то выше 125. Медленное и устойчивое увеличение потоков ThreadPool в сочетании с загрузкой ЦП гораздо менее 100 % являются ключевыми сигналами о том, что нехватка ThreadPool в настоящее время является узким местом производительности. Увеличение числа потоков будет продолжаться до тех пор, пока пул не достигнет максимального количества потоков, не будет создано достаточное количество потоков для удовлетворения всех входящих рабочих элементов или загрузка ЦП. Часто, но не всегда, при нехватке 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 задач. Нехватка ThreadPool по-прежнему может происходить с этими API, но длительность гораздо короче, чем в старых версиях .NET, так как среда выполнения реагирует быстрее. Снова запустите Bombardier с конечной api/diagscenario/taskwait точкой:
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s
В .NET 6 следует наблюдать, как пул увеличивает число потоков быстрее, чем раньше, а затем стабилизируется при большом количестве потоков. Во время масштабирования числа потоков происходит голодание ThreadPool.
Разрешение нехватки ThreadPool
Чтобы избежать нехватки ThreadPool, потоки ThreadPool должны оставаться разблокированы, чтобы они были доступны для обработки входящих рабочих элементов. Существует два способа определить, что делает каждый поток: с помощью средства dotnet-stack или захвата дампа с dotnet-dump , который можно просмотреть в Visual Studio. 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()
Кадры, расположенные вверху, показывают, что поток заблокирован при вызове GetResultCore(bool) функции 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()
Теперь вы можете перейти к коду для этого контроллера в файле 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 показывает, что число потоков ThreadPool остается гораздо ниже, а средняя задержка остается почти 500 мс при использовании подхода 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
