Ищем дедлок в .NET 5 с помощью анализа дампа

В жизни каждого инженера может произойти ситуация, когда процесс его приложения «завис» и не выполняет ту работу, которую должен. Причины могут быть разные и чтобы узнать их, нужно заглянуть во внутренности процесса и расследовать, что же там происходит. Для этого, можно снять дамп и проанализировать его. Каждый такой случай уникальный, но подходы к анализу дампов — общие. В этой статье я покажу, как расследовал одну из подобных ситуаций и пришёл к неожиданным выводам.

Вводная

Подобные истории всегда начинаются с того, что существует какой-то .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

Выполняем уже родные нам команды 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 в этой же библиотеке, в окрестностях классов, которые были рассмотрены в этой статье и вправду был дедлок, так что кто знает, сколько ещё таких статей придётся написать :)

Не оставляйте в стороне такой инструмент как анализ дампов, пользуйтесь им. В данном случае можно было бы прибить процесс насильно и всё, ведь баг воспроизводился редко. Но анализировать дампы увлекательно, а главное, появляется понимание корня проблемы, что позволяет от неё избавиться.