Depuración de un interbloqueo en .NET Core
Este artículo se aplica a: ✔️ SDK de .NET Core 3.1 y versiones posteriores
En este tutorial se explica cómo depurar un escenario de interbloqueo. Con el repositorio de código fuente de ejemplo proporcionado, Aplicación web de ASP.NET Core, puede provocar un interbloqueo de forma intencionada. El punto de conexión dejará de responder y experimentará una acumulación de subprocesos. Así, aprenderá a usar diversas herramientas para analizar el problema, como los volcados de núcleo, el análisis de volcados de núcleo y el seguimiento de procesos.
En este tutorial va a:
- Investigar una aplicación que ha dejado de responder
- Generar un archivo de volcado de núcleo
- Analizar los subprocesos del proceso en el archivo de volcado de memoria
- Analizar pilas de llamadas y bloques de sincronización
- Diagnosticar y solucionar un interbloqueo
Requisitos previos
En el tutorial se usa:
- SDK de .NET Core 3.1 o una versión posterior
- Destino de depuración de ejemplo: aplicación web para desencadenar el escenario
- dotnet-trace para mostrar procesos
- dotnet-dump para recopilar y analizar un archivo de volcado de memoria
Generación de volcado de núcleo
A la hora de investigar la falta de respuesta de una aplicación, un volcado de núcleo o memoria permite inspeccionar el estado de sus subprocesos y cualquier posible bloqueo que pueda tener problemas de contención. Ejecute la aplicación de depuración de ejemplo mediante el siguiente comando desde el directorio raíz de ejemplo:
dotnet run
Para encontrar el identificador de proceso, use el comando siguiente:
dotnet-trace ps
Anote el identificador de proceso de la salida del comando. El identificador de proceso era 4807, pero el suyo será diferente. Vaya a la siguiente dirección URL, que es un punto de conexión de API en el sitio de ejemplo:
https://localhost:5001/api/diagscenario/deadlock
La solicitud de API al sitio dejará de responder. Deje que la solicitud se ejecute durante unos 10 o 15 segundos. Luego, cree el volcado de núcleo mediante el siguiente comando:
Análisis del volcado de memoria principal
Para iniciar el análisis de volcado de núcleo, ábralo con el siguiente comando dotnet-dump analyze. El argumento es la ruta de acceso al archivo de volcado de núcleo recopilado anteriormente.
dotnet-dump analyze ~/.dotnet/tools/core_20190513_143916
Puesto que está examinando una posible aplicación que no responde, quiere obtener una idea general de la actividad de los subprocesos del proceso. Puede usar el comando threads como se muestra a continuación:
> threads
*0 0x1DBFF (121855)
1 0x1DC01 (121857)
2 0x1DC02 (121858)
3 0x1DC03 (121859)
4 0x1DC04 (121860)
5 0x1DC05 (121861)
6 0x1DC06 (121862)
7 0x1DC07 (121863)
8 0x1DC08 (121864)
9 0x1DC09 (121865)
10 0x1DC0A (121866)
11 0x1DC0D (121869)
12 0x1DC0E (121870)
13 0x1DC10 (121872)
14 0x1DC11 (121873)
15 0x1DC12 (121874)
16 0x1DC13 (121875)
17 0x1DC14 (121876)
18 0x1DC15 (121877)
19 0x1DC1C (121884)
20 0x1DC1D (121885)
21 0x1DC1E (121886)
22 0x1DC21 (121889)
23 0x1DC22 (121890)
24 0x1DC23 (121891)
25 0x1DC24 (121892)
26 0x1DC25 (121893)
...
...
317 0x1DD48 (122184)
318 0x1DD49 (122185)
319 0x1DD4A (122186)
320 0x1DD4B (122187)
321 0x1DD4C (122188)
La salida muestra todos los subprocesos que se están ejecutando en el proceso con su identificador de subproceso de depurador asociado y su identificador de subproceso de sistema operativo. Hay más de 300 subprocesos en función de la salida.
El siguiente paso es entender mejor lo que los subprocesos están haciendo mediante la obtención de la pila de llamadas de cada subproceso. El comando clrstack se puede usar para generar pilas de llamadas. Puede generar una sola pila de llamadas o todas. Use el siguiente comando para generar todas las pilas de llamadas de todos los subprocesos del proceso:
clrstack -all
Una parte representativa de la salida tiene el siguiente aspecto:
...
...
...
Child SP IP Call Site
00007F2AE37B5680 00007f305abc6360 [GCFrame: 00007f2ae37b5680]
00007F2AE37B5770 00007f305abc6360 [GCFrame: 00007f2ae37b5770]
00007F2AE37B57D0 00007f305abc6360 [HelperMethodFrame_1OBJ: 00007f2ae37b57d0] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
00007F2AE37B5920 00007F2FE392B31F testwebapi.Controllers.DiagScenarioController.<deadlock>b__3_1() [/home/marioh/webapi/Controllers/diagscenario.cs @ 36]
00007F2AE37B5950 00007F2FE392B46D System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/__w/3/s/src/System.Private.CoreLib/shared/System/Threading/ExecutionContext.cs @ 201]
00007F2AE37B5CA0 00007f30593044af [GCFrame: 00007f2ae37b5ca0]
00007F2AE37B5D70 00007f30593044af [DebuggerU2MCatchHandlerFrame: 00007f2ae37b5d70]
OS Thread Id: 0x1dc82
Child SP IP Call Site
00007F2AE2FB4680 00007f305abc6360 [GCFrame: 00007f2ae2fb4680]
00007F2AE2FB4770 00007f305abc6360 [GCFrame: 00007f2ae2fb4770]
00007F2AE2FB47D0 00007f305abc6360 [HelperMethodFrame_1OBJ: 00007f2ae2fb47d0] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
00007F2AE2FB4920 00007F2FE392B31F testwebapi.Controllers.DiagScenarioController.<deadlock>b__3_1() [/home/marioh/webapi/Controllers/diagscenario.cs @ 36]
00007F2AE2FB4950 00007F2FE392B46D System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/__w/3/s/src/System.Private.CoreLib/shared/System/Threading/ExecutionContext.cs @ 201]
00007F2AE2FB4CA0 00007f30593044af [GCFrame: 00007f2ae2fb4ca0]
00007F2AE2FB4D70 00007f30593044af [DebuggerU2MCatchHandlerFrame: 00007f2ae2fb4d70]
OS Thread Id: 0x1dc83
Child SP IP Call Site
00007F2AE27B3680 00007f305abc6360 [GCFrame: 00007f2ae27b3680]
00007F2AE27B3770 00007f305abc6360 [GCFrame: 00007f2ae27b3770]
00007F2AE27B37D0 00007f305abc6360 [HelperMethodFrame_1OBJ: 00007f2ae27b37d0] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
00007F2AE27B3920 00007F2FE392B31F testwebapi.Controllers.DiagScenarioController.<deadlock>b__3_1() [/home/marioh/webapi/Controllers/diagscenario.cs @ 36]
00007F2AE27B3950 00007F2FE392B46D System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/__w/3/s/src/System.Private.CoreLib/shared/System/Threading/ExecutionContext.cs @ 201]
00007F2AE27B3CA0 00007f30593044af [GCFrame: 00007f2ae27b3ca0]
00007F2AE27B3D70 00007f30593044af [DebuggerU2MCatchHandlerFrame: 00007f2ae27b3d70]
OS Thread Id: 0x1dc84
Child SP IP Call Site
00007F2AE1FB2680 00007f305abc6360 [GCFrame: 00007f2ae1fb2680]
00007F2AE1FB2770 00007f305abc6360 [GCFrame: 00007f2ae1fb2770]
00007F2AE1FB27D0 00007f305abc6360 [HelperMethodFrame_1OBJ: 00007f2ae1fb27d0] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
00007F2AE1FB2920 00007F2FE392B31F testwebapi.Controllers.DiagScenarioController.<deadlock>b__3_1() [/home/marioh/webapi/Controllers/diagscenario.cs @ 36]
00007F2AE1FB2950 00007F2FE392B46D System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/__w/3/s/src/System.Private.CoreLib/shared/System/Threading/ExecutionContext.cs @ 201]
00007F2AE1FB2CA0 00007f30593044af [GCFrame: 00007f2ae1fb2ca0]
00007F2AE1FB2D70 00007f30593044af [DebuggerU2MCatchHandlerFrame: 00007f2ae1fb2d70]
OS Thread Id: 0x1dc85
Child SP IP Call Site
00007F2AE17B1680 00007f305abc6360 [GCFrame: 00007f2ae17b1680]
00007F2AE17B1770 00007f305abc6360 [GCFrame: 00007f2ae17b1770]
00007F2AE17B17D0 00007f305abc6360 [HelperMethodFrame_1OBJ: 00007f2ae17b17d0] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
00007F2AE17B1920 00007F2FE392B31F testwebapi.Controllers.DiagScenarioController.<deadlock>b__3_1() [/home/marioh/webapi/Controllers/diagscenario.cs @ 36]
00007F2AE17B1950 00007F2FE392B46D System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/__w/3/s/src/System.Private.CoreLib/shared/System/Threading/ExecutionContext.cs @ 201]
00007F2AE17B1CA0 00007f30593044af [GCFrame: 00007f2ae17b1ca0]
00007F2AE17B1D70 00007f30593044af [DebuggerU2MCatchHandlerFrame: 00007f2ae17b1d70]
OS Thread Id: 0x1dc86
Child SP IP Call Site
00007F2AE0FB0680 00007f305abc6360 [GCFrame: 00007f2ae0fb0680]
00007F2AE0FB0770 00007f305abc6360 [GCFrame: 00007f2ae0fb0770]
00007F2AE0FB07D0 00007f305abc6360 [HelperMethodFrame_1OBJ: 00007f2ae0fb07d0] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
00007F2AE0FB0920 00007F2FE392B31F testwebapi.Controllers.DiagScenarioController.<deadlock>b__3_1() [/home/marioh/webapi/Controllers/diagscenario.cs @ 36]
00007F2AE0FB0950 00007F2FE392B46D System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/__w/3/s/src/System.Private.CoreLib/shared/System/Threading/ExecutionContext.cs @ 201]
00007F2AE0FB0CA0 00007f30593044af [GCFrame: 00007f2ae0fb0ca0]
00007F2AE0FB0D70 00007f30593044af [DebuggerU2MCatchHandlerFrame: 00007f2ae0fb0d70]
OS Thread Id: 0x1dc87
Child SP IP Call Site
00007F2AE07AF680 00007f305abc6360 [GCFrame: 00007f2ae07af680]
00007F2AE07AF770 00007f305abc6360 [GCFrame: 00007f2ae07af770]
00007F2AE07AF7D0 00007f305abc6360 [HelperMethodFrame_1OBJ: 00007f2ae07af7d0] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
00007F2AE07AF920 00007F2FE392B31F testwebapi.Controllers.DiagScenarioController.<deadlock>b__3_1() [/home/marioh/webapi/Controllers/diagscenario.cs @ 36]
00007F2AE07AF950 00007F2FE392B46D System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/__w/3/s/src/System.Private.CoreLib/shared/System/Threading/ExecutionContext.cs @ 201]
00007F2AE07AFCA0 00007f30593044af [GCFrame: 00007f2ae07afca0]
00007F2AE07AFD70 00007f30593044af [DebuggerU2MCatchHandlerFrame: 00007f2ae07afd70]
OS Thread Id: 0x1dc88
Child SP IP Call Site
00007F2ADFFAE680 00007f305abc6360 [GCFrame: 00007f2adffae680]
00007F2ADFFAE770 00007f305abc6360 [GCFrame: 00007f2adffae770]
00007F2ADFFAE7D0 00007f305abc6360 [HelperMethodFrame_1OBJ: 00007f2adffae7d0] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
00007F2ADFFAE920 00007F2FE392B31F testwebapi.Controllers.DiagScenarioController.<deadlock>b__3_1() [/home/marioh/webapi/Controllers/diagscenario.cs @ 36]
00007F2ADFFAE950 00007F2FE392B46D System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/__w/3/s/src/System.Private.CoreLib/shared/System/Threading/ExecutionContext.cs @ 201]
00007F2ADFFAECA0 00007f30593044af [GCFrame: 00007f2adffaeca0]
00007F2ADFFAED70 00007f30593044af [DebuggerU2MCatchHandlerFrame: 00007f2adffaed70]
...
...
Si se observan las pilas de llamadas de los más de 300 subprocesos, se muestra un patrón en el que una mayoría de los subprocesos comparten una pila de llamadas común:
OS Thread Id: 0x1dc88
Child SP IP Call Site
00007F2ADFFAE680 00007f305abc6360 [GCFrame: 00007f2adffae680]
00007F2ADFFAE770 00007f305abc6360 [GCFrame: 00007f2adffae770]
00007F2ADFFAE7D0 00007f305abc6360 [HelperMethodFrame_1OBJ: 00007f2adffae7d0] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
00007F2ADFFAE920 00007F2FE392B31F testwebapi.Controllers.DiagScenarioController.<deadlock>b__3_1() [/home/marioh/webapi/Controllers/diagscenario.cs @ 36]
00007F2ADFFAE950 00007F2FE392B46D System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/__w/3/s/src/System.Private.CoreLib/shared/System/Threading/ExecutionContext.cs @ 201]
00007F2ADFFAECA0 00007f30593044af [GCFrame: 00007f2adffaeca0]
00007F2ADFFAED70 00007f30593044af [DebuggerU2MCatchHandlerFrame: 00007f2adffaed70]
La pila de llamadas parece mostrar que la solicitud ha llegado en el método de interbloqueo que, a su vez, realiza una llamada a Monitor.ReliableEnter. Este método indica que los subprocesos están intentando especificar un bloqueo de monitor. Están esperando a que el bloqueo esté disponible. Probablemente otro subproceso lo haya bloqueado.
El siguiente paso es averiguar qué subproceso está manteniendo realmente el bloqueo de monitor. Como los monitores normalmente almacenan información de bloqueo en la tabla de bloques de sincronización, se puede usar el comando syncblk para obtener más información:
> syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner
43 00000246E51268B8 603 1 0000024B713F4E30 5634 28 00000249654b14c0 System.Object
44 00000246E5126908 3 1 0000024B713F47E0 51d4 29 00000249654b14d8 System.Object
-----------------------------
Total 344
CCW 1
RCW 2
ComClassFactory 0
Free 0
Las dos columnas que interesan son MonitorHeld y Owning Thread Info. La columna MonitorHeld muestra si un subproceso ha adquirido un bloqueo de monitor y el número de subprocesos en espera. La columna Owning Thread Info muestra el subproceso que posee actualmente el bloqueo de monitor. La información del subproceso tiene tres subcolumnas diferentes. La segunda subcolumna muestra el identificador de subproceso de sistema operativo.
En este punto, se sabe que dos subprocesos diferentes (0x5634 y 0x51d4) mantienen un bloqueo de monitor. El siguiente paso consiste en echar un vistazo a lo que están haciendo esos subprocesos. Hay que comprobar si mantienen el bloqueo indefinidamente. Vamos a usar los comandos setthread y clrstack para alternar entre cada uno de los subprocesos y mostrar las pilas de llamadas.
Para ver el primer subproceso, ejecute el comando setthread y busque el índice del subproceso 0x5634 (el índice era 28). La función de interbloqueo está esperando a adquirir un bloqueo, pero ya posee dicho bloqueo. Está en interbloqueo, a la espera del bloqueo que ya mantiene.
> setthread 28
> clrstack
OS Thread Id: 0x5634 (28)
Child SP IP Call Site
0000004E46AFEAA8 00007fff43a5cbc4 [GCFrame: 0000004e46afeaa8]
0000004E46AFEC18 00007fff43a5cbc4 [GCFrame: 0000004e46afec18]
0000004E46AFEC68 00007fff43a5cbc4 [HelperMethodFrame_1OBJ: 0000004e46afec68] System.Threading.Monitor.Enter(System.Object)
0000004E46AFEDC0 00007FFE5EAF9C80 testwebapi.Controllers.DiagScenarioController.DeadlockFunc() [C:\Users\dapine\Downloads\Diagnostic_scenarios_sample_debug_target\Controllers\DiagnosticScenarios.cs @ 58]
0000004E46AFEE30 00007FFE5EAF9B8C testwebapi.Controllers.DiagScenarioController.<deadlock>b__3_0() [C:\Users\dapine\Downloads\Diagnostic_scenarios_sample_debug_target\Controllers\DiagnosticScenarios.cs @ 26]
0000004E46AFEE80 00007FFEBB251A5B System.Threading.ThreadHelper.ThreadStart_Context(System.Object) [/_/src/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs @ 44]
0000004E46AFEEB0 00007FFE5EAEEEEC System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/_/src/System.Private.CoreLib/shared/System/Threading/ExecutionContext.cs @ 201]
0000004E46AFEF20 00007FFEBB234EAB System.Threading.ThreadHelper.ThreadStart() [/_/src/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs @ 93]
0000004E46AFF138 00007ffebdcc6b63 [GCFrame: 0000004e46aff138]
0000004E46AFF3A0 00007ffebdcc6b63 [DebuggerU2MCatchHandlerFrame: 0000004e46aff3a0]
El segundo subproceso es similar. También está intentando adquirir un bloqueo que ya posee. Lo más probable es que los más de 300 subprocesos restantes en espera estén esperando también a uno de los bloqueos que han causado el interbloqueo.
Consulte también
- dotnet-trace para mostrar procesos
- dotnet-counters para comprobar el uso de memoria administrada
- dotnet-dump para recopilar y analizar un archivo de volcado de memoria
- dotnet/diagnostics
Pasos siguientes
Comentarios
Próximamente: A lo largo de 2024 iremos eliminando gradualmente las Cuestiones de GitHub como mecanismo de retroalimentación para el contenido y lo sustituiremos por un nuevo sistema de retroalimentación. Para más información, consulta: https://aka.ms/ContentUserFeedback.
Enviar y ver comentarios de