Depuración de la inanición de ThreadPool
Este artículo se aplica a: ✔️ .NET Core 3.1 y versiones posteriores
En este tutorial se explica cómo depurar un escenario de inanición de ThreadPool. La inanición de ThreadPool se produce cuando el grupo no tiene subprocesos disponibles para procesar nuevos elementos de trabajo. A menudo, esto hace que las aplicaciones respondan lentamente. Con el ejemplo proporcionado, Aplicación web ASP.NET Core, puede provocar la inanición de ThreadPool intencionadamente y aprender a diagnosticarla.
En este tutorial va a:
- Investigar una aplicación que responde lentamente a las solicitudes
- Use la herramienta dotnet-counters para identificar el colapso de ThreadPool.
- Usar la herramienta dotnet-stack para descubrir cuál es el trabajo que tiene ocupados a los subprocesos de ThreadPool
Requisitos previos
En el tutorial se usa:
- SDK de .NET Core 6.0 para compilar y ejecutar la aplicación de ejemplo
- Aplicación web de ejemplo para demostrar el comportamiento de inanición de ThreadPool
- Bombardier para generar carga para la aplicación web de ejemplo
- dotnet-counters para observar los contadores de rendimiento
- dotnet-stack para examinar las pilas de subprocesos
Ejecución de la aplicación de ejemplo
Descargue el código de la aplicación de ejemplo y compílelo mediante el SDK de .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.26Ejecute la aplicación:
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
Si usa un explorador web y envía solicitudes a https://localhost:5001/api/diagscenario/taskwait, debería ver la respuesta success:taskwait devuelta después de unos 500 ms. Esto muestra que el servidor web atiende el tráfico según lo previsto.
Observación del rendimiento lento
El servidor web de demostración tiene varios puntos de conexión que simulan realizar una solicitud de base de datos y después devuelven una respuesta al usuario. Cada uno de estos puntos de conexión tiene un retraso de aproximadamente 500 ms al atender solicitudes de una en una, pero el rendimiento es mucho peor cuando el servidor web está sujeto a cargas. Descargue la herramienta de pruebas de carga de Bombardier y observe la diferencia en la latencia cuando se envían 125 solicitudes simultáneas a cada punto de conexión.
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
Este segundo punto de conexión usa un patrón de código que funciona aún peor:
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
Ambos puntos de conexión tienen una latencia considerablemente superior a la media de 500 ms cuando la carga es alta (3,48 s. y 15,42 s. respectivamente). Si ejecuta este ejemplo en una versión anterior de .NET Core, es probable que ambos ejemplos funcionen igual de mal. .NET 6 ha actualizado la heurística de ThreadPool, que reduce el impacto en el rendimiento del patrón de codificación incorrecto que se ha usado en el primer ejemplo.
Detección de la inanición de ThreadPool
Si observó el comportamiento anterior en un servicio de trabajo real, vio la respuesta lenta a la carga pero no supo el motivo de esta. dotnet-counters es una herramienta que puede mostrar contadores de rendimiento en vivo. Estos contadores pueden proporcionar pistas sobre algunos problemas y suelen ser fáciles de obtener. En entornos de producción, es posible que tenga contadores similares proporcionados por herramientas de supervisión remota y paneles web. Instale dotnet-counters y empiece a supervisar el servicio 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
Los contadores anteriores son un ejemplo de lo que se mostraría si el servidor web no atendiera ninguna solicitud. Vuelva a ejecutar Bombardier con el punto de conexión api/diagscenario/tasksleepwait y la carga sostenida durante 2 minutos. Así habrá tiempo de sobra para observar lo que sucede con los contadores de rendimiento.
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/tasksleepwait -d 120s
La inanición de ThreadPool se produce cuando no hay subprocesos libres para controlar los elementos de trabajo en cola. La respuesta del runtime consiste en aumentar el número de subprocesos de ThreadPool. Debe observar cómo el ThreadPool Thread Count aumenta rápidamente, hasta multiplicar por dos o por tres el número de núcleos del procesador de la máquina. Después, se agregan más subprocesos, de uno a dos por segundo, hasta que finalmente se estabilizan en una cantidad que suele ser superior a 125. El aumento lento y constante de los subprocesos de ThreadPool, junto con un uso de la CPU muy por debajo del 100 %, son las señales clave de que la inanición de ThreadPool se ha convertido en un cuello de botella del rendimiento. El aumento del número de subprocesos continuará hasta que el grupo alcance el número máximo de subprocesos, se hayan creado suficientes subprocesos para satisfacer todos los elementos de trabajo entrantes o la CPU se haya saturado. A menudo, pero no siempre, la inanición de ThreadPool también mostrará valores grandes para ThreadPool Queue Length y valores bajos para ThreadPool Completed Work Item Count, lo que significa que hay una gran cantidad de trabajo pendiente y que el trabajo que se está completando es escaso. Este es un ejemplo de lo que muestran los contadores mientras el número de subprocesos sigue aumentando:
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 vez que el número de subprocesos de ThreadPool se estabiliza, el grupo ya no está en inanición. Pero si se estabiliza en un valor alto (más de tres veces el número de núcleos del procesador), normalmente esto indica que el código de la aplicación está bloqueando algunos subprocesos de ThreadPool, y que ThreadPool está compensándolo realizando su ejecución con más subprocesos. La ejecución estable cuando hay un número elevado de subprocesos no tendrá necesariamente grandes impactos en la latencia de solicitudes, pero si la carga varía drásticamente con el tiempo o si la aplicación se reinicia periódicamente, entonces es probable que, cada vez que esto ocurra, ThreadPool entre en un período de inanición. en el que aumenta lentamente el número de subprocesos y proporciona una latencia de solicitud deficiente. Cada subproceso también consume memoria, por lo que reducir el número total de subprocesos necesarios proporciona otra ventaja.
A partir de .NET 6, se modificó la heurística de ThreadPool para escalar verticalmente el número de subprocesos de ThreadPool mucho más rápido, en respuesta a ciertas API de tarea que suponen un bloqueo. La inanición de ThreadPool todavía puede producirse con estas API, pero la duración es mucho más breve que con versiones anteriores de .NET, ya que el runtime responde más rápidamente. Ejecute Bombardier de nuevo con el punto de conexión api/diagscenario/taskwait:
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s
En .NET 6, debe observar que el grupo aumenta el número de subprocesos más rápidamente que antes y que se estabiliza al alcanzar un número elevado de estos. La inanición de ThreadPool se está produciendo mientras el número de subprocesos está aumentando.
Acabar con la inanición de ThreadPool
Para eliminar la inanición de ThreadPool, sus subprocesos deben permanecer desbloqueados. Así, estarán disponibles para controlar los elementos de trabajo entrantes. Hay dos formas de averiguar lo que hacía cada subproceso: con la herramienta dotnet-stack o capturando un volcado con dotnet-dump, algo que puede verse en Visual Studio. dotnet-stack puede ser más rápido porque muestra las pilas de subprocesos inmediatamente en la consola, pero la depuración de volcado de Visual Studio ofrece mejores visualizaciones, que asignan marcos al origen; “Solo mi código” puede filtrar los marcos de implementación del runtime y la característica Pilas paralelas puede ayudar a agrupar grandes cantidades de subprocesos con pilas similares. En este tutorial se muestra la opción dotnet-stack. Consulte el vídeo del tutorial para el diagnóstico de inanición de ThreadPool para obtener un ejemplo de investigación de las pilas de subprocesos mediante Visual Studio.
Vuelva a ejecutar Bombardier para poner el servidor web bajo carga:
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s
Después, ejecute dotnet-stack para ver los seguimientos de la pila de subprocesos:
dotnet-stack report -n DiagnosticScenarios
Debería ver una salida larga que contiene un gran número de pilas. Muchas tendrán un aspecto similar a este:
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()
Los marcos de la parte inferior de estas pilas indican que estos subprocesos son de ThreadPool:
System.Private.CoreLib.il!System.Threading.ThreadPoolWorkQueue.Dispatch()
System.Private.CoreLib.il!System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()
Y los marcos situados cerca de la parte superior revelan que el subproceso está bloqueado en una llamada a GetResultCore(bool) desde la función 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()
Ahora puede ir al código de este controlador en el archivo Controllers/DiagnosticScenarios.cs de la aplicación de ejemplo para ver que llama a una API asincrónica sin usar await. Este es el patrón de código sync-over-async, del que se sabe que bloquea subprocesos y es la causa más habitual de la inanición de ThreadPool.
public ActionResult<string> TaskWait()
{
// ...
Customer c = PretendQueryCustomerFromDbAsync("Dana").Result;
return "success:taskwait";
}
En este caso, el código se puede cambiar fácilmente para usar en su lugar async/await, como se muestra en el punto de conexión TaskAsyncWait(). El uso de await permite que el subproceso actual atienda otros elementos de trabajo mientras la consulta de la base de datos está en curso. Una vez completada la búsqueda de la base de datos, se reanudará la ejecución de un subproceso de ThreadPool. De este modo, no se bloquea ningún subproceso en el código durante cada solicitud:
public async Task<ActionResult<string>> TaskAsyncWait()
{
// ...
Customer c = await PretendQueryCustomerFromDbAsync("Dana");
return "success:taskasyncwait";
}
La ejecución de Bombardier para enviar carga al punto de conexión api/diagscenario/taskasyncwait muestra que el número de subprocesos de ThreadPool se mantiene muy por debajo y que la latencia media permanece cerca de 500 ms al usar el enfoque 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
