Поиск неисправностей с помощью WinDbg, Sos и Sosex28.04.2017 16:03

591303c39ec845568c47a1ac6f87e5e4.jpg


Изображение: Julien Dumont, Flickr


К сожалению, иногда случаются ситуации, когда система перестает работать или начинает безудержно потреблять ресурсы, а логи и системные метрики не могут помочь. Ситуация еще усугубляется тем, что на системе в продакшене нет Visual Studio или какого-либо отладчика, невозможно поотлаживаться удаленно. Чаще всего даже нет возможности получить доступ этой машине. В данном случае единственным решением является анализ дампа памяти процесса. Я хочу описать несколько общих сценариев поиска проблем на таких дампах. Это поиск взаимоблокировок, утечек памяти и высокого потребления процессорных ресурсов.


Особенность таких проблем в том, что они крайне редко воспроизводятся на компьютерах разработчиков, сложно покрываются автоматизированным тестированием и для их появления нужны большие ресурсы. Поэтому важным этапом при разработке системы является проведение серий нагрузочных тестов на железе, приближенным к такому, на котором она будет работать у заказчика. При проявлении таких проблем сразу же проводить анализ и исправлять.


Дамп памяти процесса можно снять разными способами. Например, в Диспетчере задач можно выделить интересующий процесс и в контекстном меню вызвать пункт «Создать файл дампа». Мне же очень помогает утилита ProcDump от Марка Руссиновича. С ее помощью можно снимать разные виды дампов по разным событиям. Например, можно снять полный дамп памяти процесса в момент, когда процесс потребляет CPU больше 30% в течение 10 секунд. В общем, очень полезная утилита.


Анализировать дампы можно различными инструментами, например, в Visual Studio или с помощью библиотеке ClrMD. Я же буду использовать WinDbg и Sos. Никаких особенных преимуществ, просто мне удобно с ними работать. Также незаменимым помощником для меня стал плагин Sosex, который очень сильно упрощает жизнь в поиске проблем и анализе.


Перед началом наших изысканий отмечу, что для удобства в WinDbg стоит настроить отладочные символы. Этот процесс уже много раз описывался на просторах интернета, поэтому я не буду повторяться, а просто приведу ссылку.


Перейдем к рассмотрению реальных сценариев. Практически все описанные сценарии возникли в реальной практике и мне или моим коллегам пришлось в свое время с ними разобраться. Но, чтобы не нарушать коммерческой тайны, я подготовил несколько демонстрационных примеров, которые иллюстрируют возникшие проблемы. Примеры можно взять здесь. Для правдоподобности будем анализировать не рабочий процесс, а его дамп. Для этого снимем полный дамп памяти процесса с командой procdump.exe -ma PID. Итак, начнем.


Поиск взаимоблокировок (пример 1-й, простой)


(Пример 01-MonitorDeadlock)


При поиске взаимоблокировок очень хорошо может помочь Sosex. Допустим, мы заметили, что наше приложение не реагирует ни на какие команды. Оно зависло. Что делать?
Запускаем WinDbg (важно, той же разрядности, что и приложение) и загружаем снятый дамп (нажимаем Ctrl+D и в диалоге выбираем файл дамп). Загружаем нужные расширения


.loadby sos clr
.load D:\utils\sosex.dll (полный путь без кавычек)

В Sosex есть прекрасная команда dlk, которая умеет искать взаимоблокировки между блоками синхронизации и/или объектами ReaderWriterLock. Запускаем ее и смотрим на результат.


0:011> !dlk
Examining SyncBlocks...
Scanning for ReaderWriterLock(Slim) instances...
Scanning for holders of ReaderWriterLock locks...
Scanning for holders of ReaderWriterLockSlim locks...
Examining CriticalSections...
Scanning for threads waiting on SyncBlocks...
Scanning for threads waiting on ReaderWriterLock locks...
Scanning for threads waiting on ReaderWriterLocksSlim locks...
Scanning for threads waiting on CriticalSections...
*DEADLOCK DETECTED*
CLR thread 0x4 holds the lock on SyncBlock 000000e2a8343ae8 OBJ:000000e2aa064348[System.Object]
...and is waiting for the lock on SyncBlock 000000e2a8343a98 OBJ:000000e2aa064330[System.Object]
CLR thread 0x3 holds the lock on SyncBlock 000000e2a8343a98 OBJ:000000e2aa064330[System.Object]
...and is waiting for the lock on SyncBlock 000000e2a8343ae8 OBJ:000000e2aa064348[System.Object]
CLR Thread 0x4 is waiting at MonitorDeadlock.Program.Thread2()(+0x2e IL,+0x8f Native) [D:\Projects\DebugExamples\MonitorDeadlock\Program.cs @ 45,5]
CLR Thread 0x3 is waiting at MonitorDeadlock.Program.Thread1()(+0x2e IL,+0x8f Native) [D:\Projects\DebugExamples\MonitorDeadlock\Program.cs @ 33,5]
1 deadlock detected.

Нам повезло! Sosex нам сразу показал, что у нас есть взаимоблокировка, на каких объектах она возникла и в каких потоках. С помощью команды threads получим полный список управляемых потоков и сопоставим идентификатор управляемого потока с внутренним идентификатором WinDbg.


0:011> !threads
                                                                                                        Lock  
       ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception
   0    1  db8 000000e2a82929e0  202a020 Preemptive  000000E2AA06C0A0:000000E2AA06DFD0 000000e2a82860e0 0     MTA 
   5    2  5d0 000000e2a830f9d0    2b220 Preemptive  0000000000000000:0000000000000000 000000e2a82860e0 0     MTA (Finalizer) 
  9    3 27bc 000000e2a835c210  202b220 Preemptive  000000E2AA06A0D8:000000E2AA06BFD0 000000e2a82860e0 1     MTA 
  10    4 27ac 000000e2a835e5e0  202b220 Preemptive  000000E2AA06EB50:000000E2AA06FFD0 000000e2a82860e0 1     MTA

Мы видим, что интересующие нас потоки 3 и 4 имеют захваченные блокировки (столбец Lock Count c 1). Теперь посмотрим стеки этих потоков, чтобы увидеть в каком месте произошла блокировка. Для этого вызовем команду ~N*! clrstack, где N — это внутренний идентификатор потока в отладчике (9 и 10). Часть вывода скрыта для краткости


0:011> ~9e!clrstack
OS Thread Id: 0x27bc (9)
        Child SP               IP Call Site
000000e2c2d4ee58 00007ffeb0de3dda [GCFrame: 000000e2c2d4ee58] 
000000e2c2d4efc8 00007ffeb0de3dda [GCFrame: 000000e2c2d4efc8] 
000000e2c2d4f008 00007ffeb0de3dda [HelperMethodFrame_1OBJ: 000000e2c2d4f008] System.Threading.Monitor.Enter(System.Object)
000000e2c2d4f100 00007ffe2a46088f MonitorDeadlock.Program.Thread1() [D:\Projects\DebugExamples\MonitorDeadlock\Program.cs @ 33]
000000e2c2d4f160 00007ffe88b1af17 System.Threading.Tasks.Task.Execute()
0:011> ~10e!clrstack
OS Thread Id: 0x27ac (10)
        Child SP               IP Call Site
000000e2c2f4eaf8 00007ffeb0de3dda [GCFrame: 000000e2c2f4eaf8] 
000000e2c2f4ec68 00007ffeb0de3dda [GCFrame: 000000e2c2f4ec68] 
000000e2c2f4eca8 00007ffeb0de3dda [HelperMethodFrame_1OBJ: 000000e2c2f4eca8] System.Threading.Monitor.Enter(System.Object)
000000e2c2f4eda0 00007ffe2a4609df MonitorDeadlock.Program.Thread2() [D:\Projects\DebugExamples\MonitorDeadlock\Program.cs @ 45]
000000e2c2f4ee00 00007ffe88b1af17 System.Threading.Tasks.Task.Execute()

Прекрасно! Теперь мы видим методы, которые вызвали взаимоблокировку. Мы имеем классический пример блокировки на двух локах.


private static void Thread1()
{
    lock (Lock1)
    lock (Lock2)
}

private static void Thread2()
{
    lock (Lock2)
    lock (Lock1)
}

Поиск взаимоблокировок (пример 2-й, не такой простой)


(Пример 02-RwlDeadlock)


Но иногда бывают ситуации, когда команда dlk не дает результата.


0:016> !dlk
Examining SyncBlocks...
Scanning for ReaderWriterLock(Slim) instances...
Scanning for holders of ReaderWriterLock locks...
Scanning for holders of ReaderWriterLockSlim locks...
Examining CriticalSections...
No deadlocks detected.

Что делать в таком случае? Мы же все равно подозреваем, что взаимоблокировка есть. Для начала посмотрим какие блоки синхронизации есть у процесса и кем они захвачены.


0:016> !SyncBlk -all
Index SyncBlock MonitorHeld Recursion Owning Thread Info  SyncBlock Owner
    1 00000082dde314a8            0         0 0000000000000000     none    00000082dfc6ac88 Microsoft.Win32.UnsafeNativeMethods+ManifestEtw+EtwEnableCallback
    2 00000082dde314f8            0         0 0000000000000000     none    00000082dfc6b340 System.__ComObject
    3 00000082dde31548            0         0 0000000000000000     none    00000082dfc6b360 System.EventHandler`1[[Windows.Foundation.Diagnostics.TracingStatusChangedEventArgs, mscorlib]]
    4 0000000000000000            0         0 0000000000000000     none           0 Free
    5 00000082dde315e8            0         0 0000000000000000     none    00000082dfc6bf40 Microsoft.Win32.UnsafeNativeMethods+ManifestEtw+EtwEnableCallback

Результатов нет. В системе ни один блок синхронизации не захвачен. Возможно, блокировка может быть на объекте ReaderWriterLock. Проверить это можно с помощью команды Sosex rwlock.


0:016> !rwlock
ReaderWriterLock instances...
Address            ReaderCount   WaitingReaderCount     WriterThread   WaitingWriterCount
-----------------------------------------------------------------------------------------
000000d380002b38             0                    0            --                       0
000000d380008fc8             0                    0            --                       3
0:016> !rwlock 000000d380008fc8
WriterThread:           0x0
WriterLevel:            0
WaitingWriterCount:     3
WriterEvent:            3d8
WaitingWriterThreadIds: 0x1,0x3,0x6
ReaderCount:            0
CurrentReaderThreadIds: None
WaitingReaderCount:     0
ReaderEvent:            384
WaitingReaderThreadIds: None

Отлично! Мы видим, что есть объект ReaderWriteerLock, у которого есть 3 потока, ожидающие блокировки на запись. Посмотрим на стеки этих потоков (не забываем сопоставить CLR идентификаторы сопоставить с внутренними идентификаторами отладчика с помощью команды threads).


0:016> ~0e!clrstack
OS Thread Id: 0x1ea0 (0)
        Child SP               IP Call Site
000000d3f69ae388 00007ffeb0de3dda [GCFrame: 000000d3f69ae388] 
000000d3f69ae3c8 00007ffeb0de3dda [HelperMethodFrame_1OBJ: 000000d3f69ae3c8] System.Threading.ReaderWriterLock.FCallUpgradeToWriterLock(System.Threading.LockCookie ByRef, Int32)
000000d3f69ae4d0 00007ffe89376fcd System.Threading.ReaderWriterLock.UpgradeToWriterLock(Int32)
000000d3f69ae510 00007ffe2a440c4f RwlDeadlock.UpgradableRwlDeadlock.GetExpensiveObject(System.String) [D:\Projects\DebugExamples\RwlDeadlock\UpgradableRwlDeadlock.cs @ 34]
000000d3f69ae5a0 00007ffe2a440b6c RwlDeadlock.UpgradableRwlDeadlock.b__2_0(Int32) [D:\Projects\DebugExamples\RwlDeadlock\UpgradableRwlDeadlock.cs @ 15]
…
0:016> ~9e!clrstack
OS Thread Id: 0x310c (9)
        Child SP               IP Call Site
000000d3f969e8d8 00007ffeb0de3dda [GCFrame: 000000d3f969e8d8] 
000000d3f969e918 00007ffeb0de3dda [HelperMethodFrame_1OBJ: 000000d3f969e918] System.Threading.ReaderWriterLock.FCallUpgradeToWriterLock(System.Threading.LockCookie ByRef, Int32)
000000d3f969ea20 00007ffe89376fcd System.Threading.ReaderWriterLock.UpgradeToWriterLock(Int32)
000000d3f969ea60 00007ffe2a440c4f RwlDeadlock.UpgradableRwlDeadlock.GetExpensiveObject(System.String) [D:\Projects\DebugExamples\RwlDeadlock\UpgradableRwlDeadlock.cs @ 34]
000000d3f969eaf0 00007ffe2a440b6c RwlDeadlock.UpgradableRwlDeadlock.b__2_0(Int32) [D:\Projects\DebugExamples\RwlDeadlock\UpgradableRwlDeadlock.cs @ 15]

Мы нашли пример неправильного использования метода UpgradeToWriterLock класса ReaderWriterLock.


Из этих примеров можно попробовать описать алгоритм, с помощью которого можно анализировать взаимоблокировки:


  1. Ищем взаимоблокировки с помощью команды dlk.
  2. Если взаимоблокировок не найдено, анализируем объекты синхронизации с помощью команд syncblk и rwlock.
  3. Анализируем стеки потоков, которые находятся в ожидании. Ищем в стеке вызов блокирующих методов. Такими методами могут быть Monitor.Enter, Task.WaitAll, ReaderWriterLock.UpgradeToWriterLock и пр.
  4. Также можно проанализировать неуправляемый поток, вызвав команду k и поискав вызов функции ntdll! NtWaitForMultipleObjects или ntdll! NtWaitForSingleObject.

Этот алгоритм помогает мне при решении, наверное, 80% проблем. Остальные 20% требуют более нетривиальных действий.


Поиск утечки памяти


(Пример 03-MemoryLeak)


Иногда может возникнуть ситуация, когда приложение начинает выделять все больше памяти, не освобождая ее. В таком случае необходимо провести анализ выделенной памяти на предмет поиска утечек. В .Net-приложениях утечки могут возникнуть, когда сборщик мусора не может освободить корни этого объекта. Источниками корней могут являться:


  • Статические объекты;
  • Регистры процессора;
  • Стек;
  • Финализируемые объекты;
  • Неуправляемые объекты,
  • Pinned-объекты (выделенные, например, с помощью ключевого слова fixed или метода GCHandle.Alloc).

Утечку памяти можно заметить на графике выделения памяти процесса. Его можно получить с помощью счетчиков производительности, посмотрев на счетчики Process\Private bytes, .Net CLT Memory# Bytes in All Heaps и пр. Но мне удобней наблюдать за графиком Private Bytes в программе Process Explorer. Если на графике мы видим, что постоянно выделяется все больше памяти, которая не освобождается, и что размер второго поколения растет. Это недвусмысленно намекает, что у нас есть утечка памяти. Снимаем дамп памяти процесса и анализируем его.


Загружаем снятый дамп в WinDbg и подключаем sos и sosex как описано выше. У sosex есть прекрасная возможность построить индекс кучи для последующего использования (команда bhi). Этот индекс помогает значительно ускорить выполнение команд анализа кучи. Например, на дампе в 5 Гигабайт выполнение команды GcRoot занимало у меня порядка 20 минут, в ее аналог из sosex mroot на построенном индексе выполнился за пару секунд.


Сначала посмотрим общую статистику выделения памяти в куче.


0:004> !HeapStat
Heap             Gen0         Gen1         Gen2          LOH
Heap0         1204664      6409008   1421466144       166272
Free space:                                                 Percentage
Heap0              24      3204400    153752240          184SOH: 10% LOH:  0%

Как и ожидалось, второе поколение разрослось до неимоверных размеров. Посмотрим статистику выделенных объектов в куче с помощью команды sosex dumpgen. Последняя версия sosex позволяет в качестве искомого поколения указать all и таким образом проанализировать всю кучу.


0:004> !dumpgen 2 -stat
       Count      Total Size      Type
-------------------------------------------------
очень много строк пропущено для краткости
           9            648   System.Int32[]
           4            760   System.Char[]
           2          1,072   System.Globalization.CultureData
          18          1,216   System.String[]
          58          3,248   System.RuntimeType
         180          7,486   System.String
      15,825        379,800   MemoryLeak.Worker
      15,824      1,012,736   System.EventHandler`1[[System.EventArgs, mscorlib]]
      15,719    153,720,802   **** FREE ****
      15,824  1,266,299,776   System.Int64[]
63,545 objects, 1,421,434,137 bytes
Total GEN 2 size: 1,421,466,144 bytes

Видно, что в куче выделено больше 15 тысяч объектов EventHandler.

0:004> !dumpgen 2 -type System.EventHandler`1[[System.EventArgs, mscorlib]]
Object             MT                    Size   Name
-------------------------------------------------------------------
очень много строк пропущено для краткости
000000b304b7de38   00007FFC2C1FA880        64   System.EventHandler`1[[System.EventArgs, mscorlib]]
000000b304ba5018   00007FFC2C1FA880        64   System.EventHandler`1[[System.EventArgs, mscorlib]]
000000b304bcc1f8   00007FFC2C1FA880        64   System.EventHandler`1[[System.EventArgs, mscorlib]]

Посмотрим на поля одного из них (последнего). В этом помогут команды sos.do или sosex.mdt


0:004> !mdt 000000b304bcc1f8
000000b304bcc1f8 (System.EventHandler`1[[System.EventArgs, mscorlib]])
    _target:000000b304bb8948 (MemoryLeak.Worker)
    _methodBase:NULL (System.Object)
    _methodPtr:00007ffbd0a500c0 (System.IntPtr)
    _methodPtrAux:0000000000000000 (System.IntPtr)
    _invocationList:NULL (System.Object)
    _invocationCount:0000000000000000 (System.IntPtr)

Обработчик событий указывает на объект класса Worker. Выберем несколько конкретных объектов EventHandler и посмотрим на их корни.


0:004> !mroot 000000b304bcc1f8
AppDomain 000000b31b3fd720: GCHandle(Pinned) @ 000000b31b5317d8
    000000b32cfa5970[System.Object[]]
    000000b31cfa35e8[MemoryLeak.GlobalNotifier]
    000000b3052faaa0[System.EventHandler`1[[System.EventArgs, mscorlib]]]
    000000b32cfa9968[System.Object[]]
    000000b304bcc1f8[System.EventHandler`1[[System.EventArgs, mscorlib]]]
0:004> !mroot 000000b304ba5018
AppDomain 000000b31b3fd720: GCHandle(Pinned) @ 000000b31b5317d8
    000000b32cfa5970[System.Object[]]
    000000b31cfa35e8[MemoryLeak.GlobalNotifier]
    000000b3052faaa0[System.EventHandler`1[[System.EventArgs, mscorlib]]]
    000000b32cfa9968[System.Object[]]
    000000b304ba5018[System.EventHandler`1[[System.EventArgs, mscorlib]]]

Видно, что оба объекта зацепились за один и тот же экземпляр класса GlobalNotifier.


0:004> !gch 000000b31b5317d8
HandleObj           HandleType    Object                Size   Data               Type
--------------------------------------------------------------------------------------
000000b31b5317d8    Pinned        000000b32cfa5970     16344                      System.Object[]
--------------------------------------------------------------------------------------
1 Handle
0:004> !mdt 000000b31cfa35e8 -r
000000b31cfa35e8 (MemoryLeak.GlobalNotifier)
    SomethingHappened:000000b3052faaa0 (System.EventHandler`1[[System.EventArgs, mscorlib]])
        _target:000000b3052faaa0 (System.EventHandler`1[[System.EventArgs, mscorlib]])
            
        _methodBase:NULL (System.Object)
        _methodPtr:00007ffbd093e5e0 (System.IntPtr)
        _methodPtrAux:00007ffc2c2d84a8 (System.IntPtr)
        _invocationList:000000b32cfa9968 (System.Object[], Elements: 16384)
        _invocationCount:0000000000003dff (System.IntPtr)

Можно сказать, что это статический объект, к которому происходит подписка события у объектов Worker. Проанализируем потоки и их стеки.


0:004> ~0e!clrstack
OS Thread Id: 0x9700 (0)
        Child SP               IP Call Site
000000b31b2ee7a8 00007ffc2fe8f833 [HelperMethodFrame: 000000b31b2ee7a8] 
000000b31b2ee910 00007ffbd0a50614 MemoryLeak.Program.Main(System.String[]) [D:\Projects\DebugExamples\MemoryLeak\Program.cs @ 19]
000000b31b2eebc0 00007ffc30094073 [GCFrame: 000000b31b2eebc0].

Что происходит в методе Main? Дизассемблируем его. У sosex есть команда muf, которая выводит агрегированный листинг IL-кода и сгенерированного ассемблерного кода. Иногда, когда нет доступа к исходникам, она может быть очень удобной. (Приведенный вывод ограничен)


0:004> !muf 00007ffbd0a50614
MemoryLeak.Program.Main(string[]): void
    obj:MemoryLeak.Worker
Notifier.SomethingHappened += obj.SomethingHappened;
    IL_003d: ldsfld MemoryLeak.Program::Notifier
    IL_0042: ldloc.0  (obj)
    IL_0043: ldftn MemoryLeak.Worker::SomethingHappened(object, System.EventArgs)
    IL_0049: newobj System.EventHandler::.ctor
    IL_004e:callvirt MemoryLeak.GlobalNotifier::add_SomethingHappened(System.EventHandler)
        00007ffb`d0a50659 488bcb          mov     rcx,rbx
        00007ffb`d0a5065c 488bd7          mov     rdx,rdi
        00007ffb`d0a5065f 3909            cmp     dword ptr [rcx],ecx
        00007ffb`d0a50661 e892faffff      call    00007ffb`d0a500f8
obj.Work();
Thread.Sleep(50);
    IL_0063: ldc.i4.s 50(0x32)
    IL_0065: call System.Threading.Thread::Sleep
    IL_006a: br.s IL_0037
while (true)

Мы имеем классический пример утечки памяти на событиях C#. В бесконечном цикле создаются новые объекты класса Worker, которые подписываются на событие GlobalNotifier.SomethingHappened. Отписка нигде не происходит, и, следовательно, сборщик мусора не может освободить выделенную память.


Попробуем составить примерный алгоритм анализа утечек памяти:


  1. С помощью команды HeapStat получаем статистику используемой памяти в куче. Анализируем размеры поколений.
  2. Командами dumpheap –stat или dumpgen all -stat анализируем статистику выделенных объектов. Ищем большое количество специфичных для приложения объектов.
  3. С помощью команды dumpgen –type TYPE получаем список адресов интересуемых объектов.
  4. Командой mroot ObjAddress получаем корни, за которые эти объекты зацепились.
  5. Анализируем корни. Для полноты картины анализируем стеки потоков приложения. Важно понимать, что накопление неосвобожденной памяти может занимать продолжительное время, и потоки могут завершаться и/или переиспользоваться из пула. В этом случае анализ стеков не даст результатов. Основным инструментов является анализ корней.

Анализ высокого потребления процессора


(Пример 04-CpuUtilization. Запустите пример и подождите минут 10–15.)


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


Снимем дамп процесса и проанализируем его. С помощью команды .time посмотрим, сколько времени наше приложение провело в пользовательском режиме, а сколько в режиме ядра.


0:008> .time
Debug session time: Mon Apr  3 17:51:18.733 2017 (UTC + 3:00)
System Uptime: 11 days 10:29:22.677
Process Uptime: 0 days 0:08:52.766
  Kernel time: 0 days 0:00:13.562
  User time: 0 days 0:14:06.968

В моем примере программа провела в режиме ядра 13 секунд, а в пользовательском режиме 14 минут. Это означает, что потоки постоянно выполняют какую-то работу и практически никогда не засыпают. Это довольно странно. В WinDbg есть команда runaway, которая может показать распределение времени выполнения по потокам.


0:008> !runaway
 User Mode Time
  Thread       Time
   4:6598      0 days 0:02:57.687
   3:47b4      0 days 0:02:52.421
   5:3370      0 days 0:02:49.390
   6:6b1c      0 days 0:02:45.921
   7:bb58      0 days 0:02:19.687
   2:b478      0 days 0:00:17.062
   0:8e10      0 days 0:00:00.015
   8:6474      0 days 0:00:00.000
   1:97f0      0 days 0:00:00.000

С параметрами по умолчанию runaway выводит только время в режиме пользователя. Мы можем видеть, что 4 потока что-то безостановочно молотят на протяжении почти 3 минут каждый. Здесь показаны системные идентификаторы потоков. С помощью команды threads получим внутренние идентификаторы отладчика и заодно посмотрим, не возникло ли никаких исключений.


0:008> !threads
                                                                                                        Lock  
       ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception
   0    1 8e10 000000eab2ad3690  202a020 Preemptive  0000000000000000:0000000000000000 000000eab2aaa950 0     MTA 
   2    2 b478 000000eab2afb6f0    2b220 Preemptive  0000000000000000:0000000000000000 000000eab2aaa950 0     MTA (Finalizer) 
   3    3 47b4 000000eab2b491a0  202b220 Preemptive  0000000000000000:0000000000000000 000000eab2aaa950 0     MTA System.Collections.Generic.KeyNotFoundException 000000eb4ff8f848
   4    4 6598 000000eab2b4a750    2b220 Preemptive  000000EBD8F91930:000000EBD8F91948 000000eab2aaa950 1024  MTA System.Collections.Generic.KeyNotFoundException 000000eb4ff8fd60
   5    5 3370 000000eab2b53a20  202b220 Preemptive  0000000000000000:0000000000000000 000000eab2aaa950 0     MTA System.Collections.Generic.KeyNotFoundException 000000eb4ff5d698
   6    6 6b1c 000000eab2b5a3d0  202b220 Preemptive  0000000000000000:0000000000000000 000000eab2aaa950 0     MTA System.Collections.Generic.KeyNotFoundException 000000eb4ff8fba8
   7    7 bb58 000000eab2b66680    21220 Cooperative 0000000000000000:0000000000000000 000000eab2aaa950 0     Ukn

Можно видеть, что во всех интересующих нас потоках возникали исключения KeyNotFoundException.


0:008> ~3e!pe
Exception object: 000000eb4ff8f848
Exception type:   System.Collections.Generic.KeyNotFoundException
Message:          Данный ключ отсутствует в словаре.
InnerException:   
StackTrace (generated):
    SP               IP               Function
    000000EACD15EF40 00007FFC2D46AF6F mscorlib_ni!System.Collections.Concurrent.ConcurrentDictionary`2[[System.Guid, mscorlib],[System.__Canon, mscorlib]].get_Item(System.Guid)+0x48720f
    000000EACD15EF80 00007FFBD0A4074A CpuUtilization!CpuUtilization.Program.ResolveAsset(System.Guid)+0x3a
StackTraceString: 
HResult: 80131577

Посмотрим на стеки потоков (приведен вывод для одного потока, стеки остальных аналогичны).


0:008> ~3e!clrstack
OS Thread Id: 0x47b4 (3)
        Child SP               IP Call Site
000000eacd15c968 00007ffc42d00c6a [GCFrame: 000000eacd15c968] 
000000eacd15caa8 00007ffc42d00c6a [GCFrame: 000000eacd15caa8] 
000000eacd15cae8 00007ffc42d00c6a [HelperMethodFrame_1OBJ: 000000eacd15cae8] System.Threading.Monitor.Enter(System.Object)
000000eacd15cbe0 00007ffc2cfe3e9d System.Collections.Concurrent.ConcurrentDictionary`2[[System.Guid, mscorlib],[System.__Canon, mscorlib]].TryAddInternal(System.Guid, System.__Canon, Boolean, Boolean, System.__Canon ByRef)
000000eacd15ccd0 00007ffc2cfe5235 System.Collections.Concurrent.ConcurrentDictionary`2[[System.Guid, mscorlib],[System.__Canon, mscorlib]].TryAdd(System.Guid, System.__Canon)
000000eacd15cd10 00007ffbd0a40811 CpuUtilization.Program.Init(System.Guid) [D:\Projects\DebugExamples\CpuUtilization\Program.cs @ 64]
000000eacd15cd40 00007ffbd0a407aa CpuUtilization.Program.ResolveAsset(System.Guid) [D:\Projects\DebugExamples\CpuUtilization\Program.cs @ 55]
...

Теперь мы знаем место в исходниках, где искать проблему. Если заглянуть в исходники примера, то можно видеть бесконечный цикл, в котором всегда происходит ошибка получения данных из ConcurrentDictionary.


Общий алгоритм поиска довольно просто:


  1. С помощью команды runaway находим самые «прожорливые» потоки.
  2. Анализируем стеки этих потоков.

В реальной жизни все намного сложней: в приложении крутятся десятки или сотни потоков, а в куче выделены миллионы объектов. Это сильно усложняет анализ, но описанные шаги неоднократно помогали мне при анализе проблем с системами. Надеюсь, что приведенные мной примеры использования WinDbg, Sos и Sosex и вам помогут облегчить жизнь и спасти немного нервных клеток.


Все исходники примеров для изучения можно взять здесь

Комментарии (0)

© Habrahabr.ru