Прежде чем перейти к статье, хочу вам представить, экономическую онлайн игру Brave Knights, в которой вы можете играть и зарабатывать. Регистируйтесь, играйте и зарабатывайте!
![](https://habrastorage.org/getpro/habr/upload_files/dc2/602/18b/dc260218bcae9be4a68d5c4d14f0b4c3.png)
В жизни каждого инженера может произойти ситуация, когда процесс его приложения «завис» и не выполняет ту работу, которую должен. Причины могут быть разные и чтобы узнать их, нужно заглянуть во внутренности процесса и расследовать, что же там происходит. Для этого, можно снять дамп и проанализировать его. Каждый такой случай уникальный, но подходы к анализу дампов — общие. В этой статье я покажу, как расследовал одну из подобных ситуаций и пришёл к неожиданным выводам.
Вводная
Подобные истории всегда начинаются с того, что существует какой-то .NET процесс, с которым что-то не так. Вот и у меня был такой процесс. Он выглядел «живым», писал логи, отправлял метрики, но полезную работу делать перестал. Конечно же, хочется разобраться в причинах такой аномалии. В этом почти всегда помогает анализ дампа процесса, ведь там можно увидеть, чем конкретно занимаются потоки приложения и какие данные лежат в памяти. Снимать и анализировать дампы можно по-разному, в этот раз я решил воспользоваться утилитой dotnet-dump. Она кроссплатформенная и является неплохой альтернативой для WinDbg. Алгоритм действий такой:
выполняем команду
dotnet dump ps
и находим тамpid
своего процесса;снимаем дамп командой
dotnet dump collect -p <pid>
;открываем дамп командой
dotnet dump analyze <dump file>
.
Теперь можно переходить к анализу.
Смотрим в кингу, видим...
Для начала хочется понять общую картину происходящего внутри процесса. Для этого, проанализируем его потоки и посмотрим, чем они заняты. Выполняем команду clrstack -all
, которая покажет стектрейсы всех управляемых потоков на момент снятия дампа. В моём случае их было немного и я сразу увидел тот поток, который должен был делать полезную работу, но не делал (лишнее вырезано за ненадобностью):
OS Thread Id: 0x346c (27)
Child SP IP Call Site
0000007C289B9CD8 00007ffeb85f0544 System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
0000007C289B9E30 00007FFEA5F22A1A System.Diagnostics.Tracing.EventListener.Dispose() [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs @ 3937]
...
Интересной является верхушка стектрейса. Из неё видно, что мы застали поток с идентификатором 0x346c
за вызовом метода System.Diagnostics.Tracing.EventListener.Dispose()
, после которого случился вызов System.Threading.Monitor.ReliableEnter
, а это, как многим известно, конструкция lock
. Заметим, что это происходит внутри .NET библиотеки System.Diagnostics.Tracing, а значит, мы можем найти это место в исходниках на github, благо в дампе есть указание нужного файла и даже строки:
public virtual void Dispose()
{
lock (EventListenersLock)
{
...
}
}
У потока не получается захватить этот лок, а значит, какой-то другой поток его уже держит. Но какой? Почему так долго не отпускает? Неужели внутри .NET случился дедлок? Для упрощения дальнейшего повествования дадим читаемое имя потоку 0x346c = EventListenerThread
и попробуем разобраться с возникшими вопросами.
Чтобы узнать, кто держит этот лок, можно воспользоваться командой syncblk
, которая покажет нам информацию о всех блокировках, которые были на момент создания дампа:
Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner
125 000001EF014F0898 3 1 000001EF01739DE0 33d0 13 000001edb76f3308 System.Object
2431 000001EF1198F598 3 1 000001EF02564EE0 2868 19 000001ed376841c8 System.Collections.Generic.List`1[[System.WeakReference`1[[System.Diagnostics.Tracing.EventSource, System.Private.CoreLib]], System.Private.CoreLib]]
Внимательнее посмотрим на вторую строчку, ведь там содержатся уже знакомые слова про System.Diagnostics.Tracing.EventSource
. Интересны колонки Thread Info
и SyncBlock
. Читать это можно так: "поток 0x2868
держит блокировку на объекте по адресу 000001ed376841c8
". Видно, что это другой поток, с другим идентификатором. Появляется гипотеза, что EventListenerThread
пытается взять лок как раз на этом объекте. Подтвердим или опровергнем это. Для этого, переключимся на EventListenerThread
командой setthread -t 0x346c
(напомню, это его идентификатор) и выполним команду clrstack -a
, которая покажет подробную информацию о локальных переменных и аргументах функций потока:
OS Thread Id: 0x346c (27)
Child SP IP Call Site
0000007C289B9CD8 00007ffeb85f0544 System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
0000007C289B9E30 00007FFEA5F22A1A System.Diagnostics.Tracing.EventListener.Dispose() [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs @ 3937]
PARAMETERS:
this (<CLR reg>) = 0x000001edb76ea040
LOCALS:
0x0000007C289B9E60 = 0x000001ed376841c8
<no data>
<no data>
<no data>
<no data>
...
В секции LOCALS
у метода System.Diagnostics.Tracing.EventListener.Dispose()
видим этот объект 0x000001ed376841c8
, гипотеза подтвердилась.
Зафиксируем промежуточный итог — EventListenerThread
пытается взять лок на объекте, которым уже владеет поток 0x2868
.
Теперь нужно понять, почему поток 0x2868
не отпускает этот лок. Для этого посмотрим на его стектрейс, уже знакомыми командами setthread -t 0x2868
и clrstack -a
:
OS Thread Id: 0x2868 (19)
Child SP IP Call Site
0000007C2AABF2B8 00007ffeb85f0544 System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
0000007C2AABF410 00007FFEA5F108B5 System.Diagnostics.Tracing.CounterGroup.OnEventSourceCommand(System.Object, System.Diagnostics.Tracing.EventCommandEventArgs) [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs @ 65]
PARAMETERS:
this (<CLR reg>) = 0x000001edb76f3390
sender = <no data>
e = <no data>
LOCALS:
<no data>
<no data>
<no data>
<no data>
0x0000007C2AABF438 = 0x000001edb76f3308
<no data>
А он и сам пытается захватить лок, но не может! Об этом нам говорит последний вызов метода System.Threading.Monitor.ReliableEnter
. Поймём, кто мешает этому потоку успешно захватить лок. В секции LOCALS
видно объект с адресом 0x000001edb76f3308
. Вспомним вывод команды syncblk
:
Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner
125 000001EF014F0898 3 1 000001EF01739DE0 33d0 13 000001edb76f3308 System.Object
2431 000001EF1198F598 3 1 000001EF02564EE0 2868 19 000001ed376841c8 System.Collections.Generic.List`1[[System.WeakReference`1[[System.Diagnostics.Tracing.EventSource, System.Private.CoreLib]], System.Private.CoreLib]]
И видим в первой строчке в точности этот объект, которым, владеет пока ещё незнакомый нам поток 0x33d0
.
Для упрощения дальнейшего повествования дадим читаемое имя потоку 0x2868 = CounterGroupThread
и зафиксируем промежуточный итог — EventListenerThread
ожидает взятие лока на 0x000001ed376841c8
, но им уже владеет CounterGroupThread
и не отпускает, потому что ожидает взятие лока на 0x000001edb76f3308
, который тоже занят потоком 0x33d0
. Тут пока ещё нет дедлока и нам ничего не остаётся, как выяснить, чем занимается поток 0x33d0
и почему он не отпускает блокировку. Может быть там дедлок? А может мы спустимся еще на уровень ниже, а потом ещё и ещё?
We need to go deeper
![](https://habrastorage.org/getpro/habr/upload_files/6d8/484/755/6d8484755a4d46b88cb1a6115166d4e5.png)
Выполняем уже родные нам команды setthread -t 0x33d0
и clrtstack
:
OS Thread Id: 0x33d0 (13)
Child SP IP Call Site
0000007C29EBF530 00007FFE485639E9 System.TimeSpan..ctor(Int32, Int32, Int32, Int32, Int32) [/_/src/libraries/System.Private.CoreLib/src/System/TimeSpan.cs @ 76]
0000007C29EBF560 00007FFEA5F11071 System.Diagnostics.Tracing.CounterGroup.OnTimer() [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs @ 241]
0000007C29EBF630 00007FFEA5F11450 System.Diagnostics.Tracing.CounterGroup+<>c__DisplayClass21_0.<PollForValues>b__0() [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs @ 274]
0000007C29EBF660 00007FFEA5F11379 System.Diagnostics.Tracing.CounterGroup.PollForValues() [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs @ 284]
0000007C29EBF710 00007FFEA5DFBF4D System.Threading.ThreadHelper.ThreadStart() [/_/src/coreclr/src/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs @ 96]
0000007C29EBFBD0 00007ffea6339413 [DebuggerU2MCatchHandlerFrame: 0000007c29ebfbd0]
Стоп, что? Видим, что этот поток мы застали за созданием TimeSpan
через конструктор. Но ведь там нет никаких локов, в чём дело? Теперь проще всего будет заглянуть в код, чтобы понять, что происходит, благо в дампе есть указание всех классов и строчек в них.
Замечание! Не стоит смотреть исходный код .NET через декомпиляцию в своей IDE, ведь ваша версия SDK может быть не такая, под какой был запущен исходный код. Чтобы узнать нужную версию, выполняем команду eeversion
:
5.0.721.25508 free
Server mode with 6 gc heaps
SOS Version: 5.0.5.1802 retail build
В моём случае это был рантайм .NET 5.0.7
и его исходники мы посмотрим на github:
lock (s_counterGroupLock)
{
_timeStampSinceCollectionStarted = now;
do
{
_nextPollingTimeStamp += new TimeSpan(0, 0, 0, 0, _pollingIntervalInMilliseconds);
} while (_nextPollingTimeStamp <= now);
}
Что же мы видим? Под локом выполняется цикл, из которого мы выходим, когда _nextPollingTimeStamp
станет больше, чем now
, который чуть раньше выставляется в DateTime.UtcNow
. Вроде бы, ничего криминального, но понятно, что где-то здесь и скрывается корень всей проблемы, ведь дальше уже некуда копать. Посмотрев код всё того же класса, можно увидеть, что _pollingIntervalInMilliseconds
может оказаться равен нулю и в таком случае, мы никогда не выйдем из цикла. Проверим, наш это случай или нет. Вызываем clrstack -a
, чтобы получить адрес объекта этого класса:
OS Thread Id: 0x33d0 (13)
Child SP IP Call Site
...
0000007C29EBF560 00007FFEA5F11071 System.Diagnostics.Tracing.CounterGroup.OnTimer() [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs @ 241]
PARAMETERS:
this (<CLR reg>) = 0x000001ebb76a7278
LOCALS:
<no data>
<no data>
<no data>
<no data>
<no data>
<no data>
<no data>
<no data>
<no data>
0x0000007C29EBF5A0 = 0x000001edb76f3308
<no data>
...
В this
мы видим адрес 0x000001ebb76a7278
, вызовем команду do 0x000001ebb76a7278
, чтобы посмотреть поля этого объекта:
Name: System.Diagnostics.Tracing.CounterGroup
MethodTable: 00007ffe47ade5d0
EEClass: 00007ffe47ac6920
Size: 56(0x38) bytes
File: C:\Program Files\dotnet\shared\Microsoft.NETCore.App\5.0.7\System.Private.CoreLib.dll
Fields:
MT Field Offset Type VT Attr Value Name
00007ffe468781d8 40019f6 8 ...acing.EventSource 0 instance 000001ed37683790 _eventSource
00007ffe47ade7c0 40019f7 10 ...Private.CoreLib]] 0 instance 000001ebb76a72b0 _counters
00007ffe4697a928 40019fa 20 System.DateTime 1 instance 000001ebb76a7298 _timeStampSinceCollectionStarted
00007ffe4679b258 40019fb 18 System.Int32 1 instance 0 _pollingIntervalInMilliseconds
00007ffe4697a928 40019fc 28 System.DateTime 1 instance 000001ebb76a72a0 _nextPollingTimeStamp
00007ffe46790c68 40019f8 1678 System.Object 0 static 000001edb76f3308 s_counterGroupLock
00007ffe47ade708 40019f9 1680 ...ivate.CoreLib]][] 0 static 000001edb76f3320 s_counterGroups
00007ffe4685a8c0 40019fd 1688 ....Threading.Thread 0 static 000001edb76f3830 s_pollingThread
00007ffe47adeed0 40019fe 1690 ...ng.AutoResetEvent 0 static 000001edb76f3780 s_pollingThreadSleepEvent
00007ffe47adef58 40019ff 1698 ...Private.CoreLib]] 0 static 000001edb76f37b8 s_counterGroupEnabledList
В колонке Value
у поля _pollingIntervalInMilliseconds
видим значение 0
, что и требовалось доказать. Таким образом, мы получили бесконечный цикл, а лок, который держит этот поток, никогда не будет освобождён.
Итоги
Подведём окончательный итог. EventListenerThread
завис в попытках взять лок на 0x000001ed376841c8
, который держит CounterGroupThread
. В свою очередь, CounterGroupThread
завис в попытках взять лок на 0x000001edb76f3308
, который держит поток 0x33d0
. А поток 0x33d0
крутится в вечном цикле. Взаимной блокировки нет, но тем не менее, потоки никогда не достигнут прогресса.
.NET пишут люди, поэтому там тоже случаются баги. Данный баг уже пофиксили в .NET 5.0.8
. В этом PR описаны ситуации, когда _pollingIntervalInMilliseconds
может стать равен нулю, одна из них — гонка внутри .NET, которая и случилась в этот раз. Хороший повод регулярно ставить патчи с обновлением рантайма.
Забавно, что до 5 версии .NET в этой же библиотеке, в окрестностях классов, которые были рассмотрены в этой статье и вправду был дедлок, так что кто знает, сколько ещё таких статей придётся написать :)
Не оставляйте в стороне такой инструмент как анализ дампов, пользуйтесь им. В данном случае можно было бы прибить процесс насильно и всё, ведь баг воспроизводился редко. Но анализировать дампы увлекательно, а главное, появляется понимание корня проблемы, что позволяет от неё избавиться.