Отладка threadPool Starvation

Статья
04/08/2023

Эта статья относится к: ✔️ .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

Поделиться через