Crash Dump Analysis

As one of the new initiatives for the Year of Debugging  DumpAnalysis Portal will publish bimonthly full color 16 page publication called:

Debugged! MZ/PE: MagaZine for/from Practicing Engineers
The only serial publication dedicated entirely to Windows® debugging

The first issue is planned for March, 2009 and will have ISBN-13: 978-1-906717-38-4. If it goes well I’m planning to have ISSN number assigned to it too. More details will be announced soon.

- Dmitry Vostokov @ DumpAnalysis.org - 

In part 1 we discussed the common mistake of not looking at full stack traces. In this part we discuss the common mistake of not looking at all stack traces. This important when the dump is partially truncated or inconsistent. For example, in one complete memory dump from one hang system WinDbg !locks command is not able to traverse them at all due to truncated dump:

3: kd> !locks
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks.......Error 1 in reading nt!_ERESOURCE.SystemResourcesList.Flink @ f71612a0

The common response, especially from beginners, would be to dismiss this dump and request the new one after increasing page file size. However, dumping all thread stacks reveals the resource contention around ERESOURCE objects similar to what was discussed in a mixed object deadlock example in kernel space: 

3: kd> !stacks
Proc.Thread  .Thread  Ticks   ThreadState Blocker
[...]
                            [85973590 csrss.exe]
4138.0051e0  85961db0 00cb222 Blocked    driverA+0xec08
4138.0048c8  85d1d240 000006d Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
4138.0054cc  85c8a840 00c0d50 Blocked    driverA+0xec08
4138.00227c  859be330 00c0d53 Blocked    driverA+0xec08
4138.0053d8  8590f458 00000df Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
4138.003bb4  85b61020 00000e1 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
4138.002a08  85d1edb0 00000e1 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
4138.005e6c  85943020 00cc9cc Blocked    driverA+0xec08
4138.00575c  858eeb40 00c0d4e Blocked    driverA+0xec08
4138.003880  858ee5f8 00c0d51 Blocked    driverA+0xec08

                            [85bb9b18 winlogon.exe]
50e0.0054d4  85a8cb30 00c0d53 Blocked    driverA+0xec08
50e0.004b90  85b6c7b8 000001a Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
50e0.0032cc  85a1f850 0000084 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
50e0.005450  85c43db0 0000014 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
50e0.005648  85a1f5e0 0000015 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
50e0.004a80  85a7abd8 000001b Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
50e0.0036d8  85d886a8 000001b Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
50e0.0055b0  85d88438 0000014 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
50e0.004380  85962020 00c0d53 Blocked    driverA+0xec08
50e0.005744  85a22db0 0000015 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
50e0.005dd4  8584c7a0 0000015 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
50e0.005e30  858902f0 0000018 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
50e0.005ce8  857bbdb0 00c0d53 Blocked    driverA+0xec08

                            [85914868 explorer.exe]
5fd8.005fdc  85911020 0000016 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5fd8.005fec  8579d020 00bc253 Blocked    driverA+0xec08
5fd8.005ff8  857ce020 0000014 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5fd8.003678  857ce8d0 00bc253 Blocked    driverA+0xec08
5fd8.00556c  857ce3f0 00b85d9 Blocked    driverA+0xec08
5fd8.005564  857e4db0 00bc253 Blocked    driverA+0xec08
5fd8.005548  86529380 00bc253 Blocked    driverA+0xec08
5fd8.006fd8  856095c8 00bc253 Blocked    driverA+0xec08
5fd8.001844  85d50020 00bc253 Blocked    driverA+0xec08
5fd8.0069cc  85ab8db0 000001a Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5fd8.0057c4  85fea2b0 00bc253 Blocked    driverA+0xec08
5fd8.00394c  85a475b8 00bc253 Blocked    driverA+0xec08
5fd8.004a8c  86090020 00bc253 Blocked    driverA+0xec08
5fd8.00583c  85990db0 00bc253 Blocked    driverA+0xec08

                            [858634a0 ApplicationA.EXE]
5b7c.005ad8  8597ddb0 0078325 Blocked    driverA+0xec08
5b7c.0058b4  85735020 00b6852 Blocked    driverA+0xec08
5b7c.00598c  8597db40 000001a Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5b7c.0059dc  85746a18 000001a Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5b7c.005b3c  85733ae8 0000016 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5b7c.005934  85733878 0000018 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5b7c.002b68  85bb8a40 0000016 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5b7c.0016dc  85747438 0000018 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5b7c.003fc0  8577ea60 00b6852 Blocked    driverA+0xec08
5b7c.0066a4  8595c2f8 0000016 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5b7c.006b50  893d5660 0000018 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5b7c.0066f4  8605f530 00b6852 Blocked    driverA+0xec08
5b7c.001554  85930cf0 00b6852 Blocked    driverA+0xec08
5b7c.006f28  86132db0 00b6852 Blocked    driverA+0xec08
5b7c.004448  85aa6890 0000016 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5b7c.000fa8  859073c8 00b6852 Blocked    driverA+0xec08

                            [8595c928 ApplicationB.exe]
5990.0059a0  857c5508 000001a Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5990.005950  85ce7548 00b3b52 Blocked    driverA+0xec08
5990.005c10  856dc910 00b3b52 Blocked    driverA+0xec08
5990.005bd4  85767b40 00b3b52 Blocked    driverA+0xec08
5990.005e38  859b6a18 000001a Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5990.005f14  85a747a0 0000015 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5990.005e68  85989020 0000015 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5990.005f10  859f42d8 0000015 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5990.005f0c  856ec5e8 00b3b52 Blocked    driverA+0xec08
5990.0045d0  856ec9a8 0000016 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5990.004584  85728020 0000018 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5990.004754  8572d818 0000016 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5990.004b94  856cf020 00b3b52 Blocked    driverA+0xec08
5990.003374  85722db0 0000016 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5990.000b1c  8647ddb0 00b3b52 Blocked    driverA+0xec08
5990.003bdc  85f812f0 00b3b52 Blocked    driverA+0xec08

                            [859bd598 dllhost.exe]
5e3c.00591c  8593e2f0 000001a Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5e3c.005e60  85777db0 000006e Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5e3c.005e64  85978b40 0000018 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19
5e3c.0055c8  85903358 0000018 Blocked    nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19

[...]

Threads Processed: 1500

Different methods to list all thread stacks are listed in Stack Trace Collection pattern. 

- Dmitry Vostokov @ DumpAnalysis.org -

Paperback edition of Memory Dump Analysis Anthology, Volume 2 is finally available on Amazon and Barnes & Noble. Search Inside is also available on Amazon. In addition, I updated the list of recommended books:

Listmania! Crash Dump Analysis and Debugging

Hardcover edition will be available on Amazon and B&N in 2-3 weeks.

- Dmitry Vostokov @ DumpAnalysis.org -

The following bugtation is quite wise and dedicated to beginners learning WinDbg (see Common Mistakes and Coincidental Symbolic Information for some examples).

“You rule the” debugger, “not the” debugger “you”.

John Dryden, The Hind and the Panther

- Dmitry Vostokov @ DumpAnalysis.org -

“Everything is memory dump.”

I’m very excited to announce that Volume 2 is available in paperback, hardcover and digital editions:

Memory Dump Analysis Anthology, Volume 2

In one or two weeks paperback edition should also appear on Amazon and other bookstores. Amazon hardcover edition is planned to be available by the end of October.

I’m often asked when Volume 3 is available and I currently plan to release it in October - November, 2009. In the mean time I’m planning to concentrate on other publishing projects. 

- Dmitry Vostokov @ DumpAnalysis.org -

The book is nearly finished and here is the final TOC:

Memory Dump Analysis Anthology, Volume 2: Table of Contents

- Dmitry Vostokov @ DumpAnalysis.org -

Mistake #2 - Not seeing semantic and pragmatic inconsistencies

Why would FreeHeap need a file name? See Incorrect Stack Trace pattern case study for semantic inconsistency. Why is this function on the stack trace

dll!exit+0x10,834

67,636 bytes long (0×10,834 in decimal)?  

The latter is an example of pragmatic inconsistency and the answer is that we don’t have symbols and the name appears from the DLL export table. The code on the stack has nothing to do with exit action when proper symbols are applied.

Another example. The memory dump of a hanging process has only one thread and it is waiting for an event. Is this the problem in ThreadProc and application logic or in the fact that _endthreadex was called when the thread was created?

STACK_TEXT: 
0379fa50 7642dcea ntdll!NtWaitForMultipleObjects+0x15
0379faec 75e08f76 kernel32!WaitForMultipleObjectsEx+0x11d
0379fb40 75e08fbf user32!RealMsgWaitForMultipleObjectsEx+0x14d
0379fb5c 00f6b45d user32!MsgWaitForMultipleObjects+0x1f
0379fba8 752e29bb application!ThreadProc+0xad
0379fbe0 752e2a47 msvcr80!_endthreadex+0×3b
0379fbe8 7649e3f3 msvcr80!_endthreadex+0xc7
0379fbf4 7773cfed kernel32!BaseThreadInitThunk+0xe
0379fc34 7773d1ff ntdll!__RtlUserThreadStart+0×23
0379fc4c 00000000 ntdll!_RtlUserThreadStart+0×1b

The latter assumption is wrong. The presence of _endthreadex stems from the fact that its address was pushed to let a user thread procedure to automatically call it upon the normal function return:  

0:000> u 752e29bb
msvcr80!_endthreadex+0x3b:
752e29bb 50              push    eax
752e29bc e8bfffffff      call    msvcr80!_endthreadex (752e2980)
752e29c1 8b45ec          mov     eax,dword ptr [ebp-14h]
752e29c4 8b08            mov     ecx,dword ptr [eax]
752e29c6 8b09            mov     ecx,dword ptr [ecx]
752e29c8 894de4          mov     dword ptr [ebp-1Ch],ecx
752e29cb 50              push    eax
752e29cc 51              push    ecx

A thread procedure passed to thread creation API call can be any C function. How would a C/C++ compiler understand that it needs to generate a call to thread exit API especially if ThreadProc is named FooBar and resides in a different compilation unit or a library? It seems logical that the runtime environment provides such an automatic return address dynamically. Also why and how _endthreadex knows about our custom ThreadProc to call it? Looks like inconsistency. The ability to see and reason about them is very important skill in memory dump analysis and debugging. The lack of sufficient unmanaged code programming experience might partly explain many analysis mistakes.

- Dmitry Vostokov @ DumpAnalysis.org -

Mistake #1 - Not looking at full stack traces

By default WinDbg cuts off stack traces after 20th line and an analyst misses essential information when looking at Stack Trace or Stack Trace Collection. Consider this thread stack trace taken from a user process dump where runaway information was not saved but customers reported CPU spikes:

0:000> ~3kvL
ChildEBP RetAddr
0290f864 773976f2 user32!_SEH_prolog+0xb
0290f86c 0047f9ec user32!EnableMenuItem+0xf
0290f884 00488f6d Application!Close+0x142c
0290f8a4 0047a9c6 Application!EnableMenu+0x5d
0290f8b8 0048890d Application!EnableWindows+0x106
0290f8d0 0048cc2b Application!SetHourGlass+0xbd
0290f8fc 0046327a Application!WriteDataStream+0x24b
0290f924 0048d8f9 Application!WriteDataStream+0x21a
0290fa68 00479811 Application!WriteDataStream+0xcb9
0290fadc 5b5e976c Application!OnWrite+0x3c1
0290fb70 5b60e0b0 mfc71!CWnd::OnWndMsg+0x4f2
0290fb90 5b60e14f mfc71!CWnd::WindowProc+0x22
0290fbf0 5b60e1b8 mfc71!AfxCallWndProc+0x91
0290fc10 00516454 mfc71!AfxWndProc+0x46
0290fc3c 7739c3b7 Application!ExitCheck+0x28f34
0290fc68 7739c484 user32!InternalCallWinProc+0x28
0290fce0 77395563 user32!UserCallWinProcCheckWow+0x151
0290fd10 773ad03f user32!CallWindowProcAorW+0x98
0290fd30 0047a59a user32!CallWindowProcA+0x1b

We can see that it uses MFC libraries and window messaging API but was it caught accidentally? Is it a typical message loop like idle message loops in Passive Thread pattern using GetMessage or it is an active GUI message pump using PeekMessage? If we expand stack trace we would see that the thread is actually MFC GUI thread that spins according to MFC source code:

int CWinThread::Run()
{
  for (;;)
  {
    while (bIdle &&
      !::PeekMessage(&(pState->m_msgCur), 
         NULL, NULL, NULL, PM_NOREMOVE))
     {

0:000> ~3kvL 100
ChildEBP RetAddr
0290f864 773976f2 user32!_SEH_prolog+0xb
0290f86c 0047f9ec user32!EnableMenuItem+0xf
0290f884 00488f6d Application!Close+0x142c
0290f8a4 0047a9c6 Application!EnableMenu+0x5d
0290f8b8 0048890d Application!EnableWindows+0x106
0290f8d0 0048cc2b Application!SetHourGlass+0xbd
0290f8fc 0046327a Application!WriteDataStream+0x24b
0290f924 0048d8f9 Application!WriteDataStream+0x21a
0290fa68 00479811 Application!WriteDataStream+0xcb9
0290fadc 5b5e976c Application!OnWrite+0x3c1
0290fb70 5b60e0b0 mfc71!CWnd::OnWndMsg+0x4f2
0290fb90 5b60e14f mfc71!CWnd::WindowProc+0x22
0290fbf0 5b60e1b8 mfc71!AfxCallWndProc+0x91
0290fc10 00516454 mfc71!AfxWndProc+0x46
0290fc3c 7739c3b7 Application!ExitCheck+0x28f34
0290fc68 7739c484 user32!InternalCallWinProc+0x28
0290fce0 77395563 user32!UserCallWinProcCheckWow+0x151
0290fd10 773ad03f user32!CallWindowProcAorW+0x98
0290fd30 0047a59a user32!CallWindowProcA+0x1b
0290fdb0 7739c3b7 Application!OnOK+0x77a
0290fddc 7739c484 user32!InternalCallWinProc+0x28
0290fe54 7739c73c user32!UserCallWinProcCheckWow+0x151
0290febc 7738e406 user32!DispatchMessageWorker+0x327
0290fecc 5b609076 user32!DispatchMessageA+0xf
0290fedc 5b60913e mfc71!AfxInternalPumpMessage+0x3e
0290fef8 004ba7cf mfc71!CWinThread::Run+0×54
0290ff04 5b61b30c Application!CMyThread::Run+0xf
0290ff84 5b869565 mfc71!_AfxThreadEntry+0×100
0290ffb8 77e66063 msvcr71!_endthreadex+0xa0
0290ffec 00000000 kernel32!BaseThreadStart+0×34

There is also WinDbg .kframes meta-command that can change default stack trace depth:

2: kd> .kframes 0n100
Default stack trace depth is 0n100 frames

- Dmitry Vostokov @ DumpAnalysis.org -