Archive for the ‘Crash Dump Patterns’ Category

Crash Dump Analysis Patterns (Part 31a)

Tuesday, November 20th, 2007

I have already discussed Passive Thread pattern in user space. In this part I continue with kernel space and passive system threads that don’t run in any user process context. These threads belong to the so called System process, don’t have any user space stack and their full stack traces can be seen from the output of !process command (if not completely paged out):

1: kd> !process 0 ff System

or from system portion of !stacks 2 command.  

Some system threads from that list belong to core OS functionality and are not passive (function offsets can vary for different OS versions and service packs):

nt!KiSwapContext+0x84
nt!KiSwapThread+0x125
nt!KeWaitForSingleObject+0x5f5
nt!MmZeroPageThread+0×180
nt!Phase1Initialization+0xe
nt!PspSystemThreadStartup+0×5b
nt!KiStartSystemThread+0×16

nt!KiSwapContext+0x84
nt!KiSwapThread+0x125
nt!KeWaitForSingleObject+0x5f5
nt!MiModifiedPageWriter+0×59
nt!PspSystemThreadStartup+0×5b
nt!KiStartSystemThread+0×16

nt!KiSwapContext+0x84
nt!KiSwapThread+0x125
nt!KeWaitForMultipleObjects+0x703
nt!MiMappedPageWriter+0xad
nt!PspSystemThreadStartup+0×5b
nt!KiStartSystemThread+0×16

nt!KiSwapContext+0x84
nt!KiSwapThread+0x125
nt!KeWaitForMultipleObjects+0x703
nt!KeBalanceSetManager+0×101
nt!PspSystemThreadStartup+0×5b
nt!KiStartSystemThread+0×16

nt!KiSwapContext+0x84
nt!KiSwapThread+0x125
nt!KeWaitForSingleObject+0x5f5
nt!KeSwapProcessOrStack+0×44
nt!PspSystemThreadStartup+0×5b
nt!KiStartSystemThread+0×16

nt!KiSwapContext+0x84
nt!KiSwapThread+0x125
nt!KeWaitForSingleObject+0x5f5
nt!EtwpLogger+0xdd
nt!PspSystemThreadStartup+0×5b
nt!KiStartSystemThread+0×16

nt!KiSwapContext+0x84
nt!KiSwapThread+0x125
nt!KeWaitForSingleObject+0x5f5
nt!KiExecuteDpc+0×198
nt!PspSystemThreadStartup+0×5b
nt!KiStartSystemThread+0×16

nt!KiSwapContext+0x84
nt!KiSwapThread+0x125
nt!KeWaitForMultipleObjects+0x703
nt!CcQueueLazyWriteScanThread+0×73
nt!PspSystemThreadStartup+0×5b
nt!KiStartSystemThread+0×16

nt!KiSwapContext+0x84
nt!KiSwapThread+0x125
nt!KeWaitForMultipleObjects+0x703
nt!ExpWorkerThreadBalanceManager+0×85
nt!PspSystemThreadStartup+0×5b
nt!KiStartSystemThread+0×16

Other threads belong to various worker queues (they can also be seen from !exqueue ff command output) and wait for data items to arrive (passive threads):

nt!KiSwapContext+0x84
nt!KiSwapThread+0x125
nt!KeRemoveQueueEx+0x848
nt!ExpWorkerThread+0×104
nt!PspSystemThreadStartup+0×5b
nt!KiStartSystemThread+0×16

or

nt!KiSwapContext+0x26
nt!KiSwapThread+0x2e5
nt!KeRemoveQueue+0x417
nt!ExpWorkerThread+0xc8
nt!PspSystemThreadStartup+0×2e
nt!KiThreadStartup+0×16

Non-Exp system threads having Worker, Logging or Logger substrings in their function names are passive threads and wait for data too, for example:

nt!KiSwapContext+0x84
nt!KiSwapThread+0x125
nt!KeWaitForMultipleObjects+0x703
nt!PfTLoggingWorker+0×81
nt!PspSystemThreadStartup+0×5b
nt!KiStartSystemThread+0×16

nt!KiSwapContext+0x84
nt!KiSwapThread+0x125
nt!KeWaitForSingleObject+0x5f5
nt!EtwpLogger+0xdd
nt!PspSystemThreadStartup+0×5b
nt!KiStartSystemThread+0×16

nt!KiSwapContext+0x84
nt!KiSwapThread+0x125
nt!KeRemoveQueueEx+0x848
nt!KeRemoveQueue+0x21
rdpdr!RxpWorkerThreadDispatcher+0×6f
nt!PspSystemThreadStartup+0×5b
nt!KiStartSystemThread+0×16

nt!KiSwapContext+0x84
nt!KiSwapThread+0x125
nt!KeWaitForSingleObject+0x5f5
HTTP!UlpThreadPoolWorker+0×26c
nt!PspSystemThreadStartup+0×5b
nt!KiStartSystemThread+0×16

nt!KiSwapContext+0x84
nt!KiSwapThread+0x125
nt!KeRemoveQueueEx+0x848
nt!KeRemoveQueue+0x21
srv2!SrvProcWorkerThread+0×74
nt!PspSystemThreadStartup+0×5b
nt!KiStartSystemThread+0×16

nt!KiSwapContext+0x84
nt!KiSwapThread+0x125
nt!KeRemoveQueueEx+0x848
nt!KeRemoveQueue+0x21
srv!WorkerThread+0×90
nt!PspSystemThreadStartup+0×5b
nt!KiStartSystemThread+0×16

Any deviations in memory dump can raise suspicion like in the stack below for driver.sys 

nt!KiSwapContext+0x26
nt!KiSwapThread+0x284
nt!KeWaitForSingleObject+0×346
nt!ExpWaitForResource+0xd5
nt!ExAcquireResourceExclusiveLite+0×8d
nt!ExEnterCriticalRegionAndAcquireResourceExclusive+0×19

driver!ProcessItem+0×2f
driver!DelayedWorker+0×27

nt!ExpWorkerThread+0×104
nt!PspSystemThreadStartup+0×5b
nt!KiStartSystemThread+0×16

- Dmitry Vostokov @ DumpAnalysis.org

NotMyLeak

Monday, November 19th, 2007

To troubleshoot and study memory leaks the following tool called NotMyLeak will be released soon. It injects different kinds of leaks into specified processes and system:

  • Process heap
  • Runtime library
  • Performance counters
  • Kernel paged pool
  • Kernel nonpaged pool
  • IRP
  • Handles
  • PTE
  • etc…

The idea is to model various real-time leaks, analyze memory dumps and then apply discovered patterns to crash dump analysis of memory dumps coming from real-world systems.   

The draft GUI (subject to change):

Note: the tool name prefix NotMy… was inspired by the name of Mark Russinovich’s tool called NotMyFault.

- Dmitry Vostokov @ DumpAnalysis.org

Memorillion and Quadrimemorillion

Thursday, November 15th, 2007

What are these? These are names of the number of possible unique complete memory dumps when address space is 32 bit and 64-bit correspondingly:

256232 and 256264

The first of them can be approximated by 101010

This idea came to me after I learnt about the so called “immense number” proposed by Walter Elsasser. This number is so big that its digits cannot be listed because there is not enough particles in observable Universe to write them.

Certainly one memorillion is more than one googol 10100 but it requires only approx. 1010 particles in ideal case to list its digits and therefore not an immense number. It is however far less than one googolplex 1010100.

Consider a complete memory dump with bytes written in hexadecimal notation:

0x50414745554d500f000000ce0e00000090...

This number has more than 8 billion digits… And it is one possible number out of memorillion of them. So one memorillion in hexadecimal notation is just

0xFFFFFFFFFFFFFFFFFFFFF... + 1

where we have 2*232 ‘F’ symbols written sequentially. One quadrimemorillion has 2*264 ‘F’ symbols.

Also the question about the number of possible crash dumps can be considered as Microsoft interview style question when you have possible candidates and you want to assess their ability to think out of the box and handle large numbers. 

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 36)

Wednesday, November 14th, 2007

The pattern I should have written as one of the first is called Local Buffer Overflow. It is observed on x86 platforms when a local variable and a function return address and/or saved frame pointer EBP are overwritten with some data. As a result, the instruction pointer EIP becomes Wild Pointer and we have a process crash in user mode or a bugcheck in kernel mode. Sometimes this pattern is diagnosed by looking at mismatched EBP and ESP values and in the case of ASCII or UNICODE buffer overflow EIP register may contain 4-char or 2-wchar_t value and ESP or EBP or both registers might point at some string fragment like in the example below:

0:000> r
eax=000fa101 ebx=0000c026 ecx=01010001 edx=bd43a010 esi=000003e0 edi=00000000
eip=0048004a esp=0012f158 ebp=00510044 iopl=0  nv up ei pl nz na po nc
cs=001b ss=0023 ds=0023 es=0023 fs=0038 gs=0000 efl=00000202
0048004a 0000 add     byte ptr [eax],al  ds:0023:000fa101=??

0:000> kL
ChildEBP RetAddr 
WARNING: Frame IP not in any known module. Following frames may be wrong.
0012f154 00420047 0x48004a
0012f158 00440077 0x420047
0012f15c 00420043 0x440077
0012f160 00510076 0x420043
0012f164 00420049 0x510076
0012f168 00540041 0x420049
0012f16c 00540041 0x540041
...
...
...

Good buffer overflow case studies with complete analysis including assembly language tutorial can be found in Buffer Overflow Attacks book.

Buy from Amazon 

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 35)

Monday, November 12th, 2007

In kernel or complete memory dumps coming from hanging or slow workstations and servers !irpfind WinDbg command may show IRP Distribution Anomaly pattern when certain drivers have excessive count of active IRPs not observed under normal circumstances. I created two IRP distribution graphs from two problem kernel dumps by preprocessing command output using Visual Studio keyboard macros to eliminate completed IRPs and then using Excel. In one case it was a big number of I/O request packets from 3rd-party antivirus filter driver:

\Driver\3rdPartyAvFilter

In the second case it was the huge number of active IRPs targeted to kernel socket ancillary function driver:

\Driver\AFD

Two other peaks on both graphs are related to NTPS and NTFS, pipes and file system and usually normal. Here is IRP distribution graph from my Vista workstation captured while I was writing this post:

- Dmitry Vostokov @ DumpAnalysis.org -

Memory Dump Analysis using Excel

Friday, November 9th, 2007

Some WinDbg commands output data in tabular format so it is possible to save their output to a text file, import it to Excel and do sorting, filtering, and graph visualization, etc. Some commands from WinDbg include:

!stacks 1

Lists all threads with Ticks column so you can sort and filter threads that had been waiting no more than 100 ticks, for
example.

!irpfind

Here we can create various histograms, for example, IRP distribution based on [Driver] column.

I’ll show more examples later but now the graph depicting thread distribution in PID - TID coordinates on a busy multiprocessor
system with 25 user sessions and more than 3,000 threads:

WinDbg scripts offer possibility to output various tabulated data via .printf:

0:000> .printf "a\tb\tc"
a       b       c

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 34)

Tuesday, November 6th, 2007

Although crash dumps are static in nature they contain Historical Information about past system dynamics that might give clues to a problem and help with troubleshooting and debugging.

For example, IRP flow between user processes and drivers is readily available in any kernel or complete memory dump. WinDbg !irpfind command will show the list of currently present I/O request packets. !irp command will give individual packet details. 

Recent Driver Verifier improvements in Vista and Windows Server 2008 allow to embed stack traces associated with IRP allocation, completion and cancellation. For information please look at the following document:

http://www.microsoft.com/whdc/devtools/tools/vistaverifier.mspx

Other information that can be included in process, kernel and complete memory dumps may reveal some history of function calls beyond the current snapshot of thread stacks:

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 33)

Monday, November 5th, 2007

If there are no CPU-bound threads on a system then most of the time processors are looping in the so called idle thread where they are halted waiting for an interrupt to occur (HLT instruction). When an interrupt occurs they process a DPC list and then do thread scheduling if necessary as evident from stack trace and its functions disassembly below. If we have a memory dump one of running threads would be the one that called KeBugCheck(Ex) function. In examples below crash dumps were generated by SystemDump application:

3: kd> !running

System Processors f (affinity mask)
  Idle Processors d

     Prcb      Current   Next
  1  f7737120  8a3da020            ................

3: kd> !thread 8a3da020 1f
THREAD 8a3da020  Cid 0ebc.0dec  Teb: 7ffdf000 Win32Thread: bc002328 RUNNING on processor 1
Not impersonating
DeviceMap                 e3e3e080
Owning Process            8a0aea88       Image:         SystemDump.exe
Wait Start TickCount      17154          Ticks: 0
Context Switch Count      568                 LargeStack
UserTime                  00:00:00.046
KernelTime                00:00:00.375
Win32 Start Address 0x0040fe92
Start Address 0x77e6b5c7
Stack Init f4266000 Current f4265c08 Base f4266000 Limit f4261000 Call 0
Priority 11 BasePriority 10 PriorityDecrement 0
ChildEBP RetAddr
f4265bec f79c9743 nt!KeBugCheckEx+0x1b
WARNING: Stack unwind information not available. Following frames may be wrong.
f4265c38 8081dce5 SystemDump+0x743
f4265c4c 808f4797 nt!IofCallDriver+0x45
f4265c60 808f5515 nt!IopSynchronousServiceTail+0x10b
f4265d00 808ee0e4 nt!IopXxxControlFile+0x5db
f4265d34 80888c6c nt!NtDeviceIoControlFile+0x2a
f4265d34 7c82ed54 nt!KiFastCallEntry+0xfc

3: kd> !ready
Processor 0: No threads in READY state
Processor 1: No threads in READY state
Processor 2: No threads in READY state
Processor 3: No threads in READY state

3: kd> ~2s

2: kd> !thread -1 1f
THREAD f7742090  Cid 0000.0000  Teb: 00000000 Win32Thread: 00000000 RUNNING on processor 2
Not impersonating
Owning Process            8089db40       Image:         Idle
Wait Start TickCount      0              Ticks: 17154 (0:00:04:28.031)
Context Switch Count      193155
UserTime                  00:00:00.000
KernelTime                00:03:23.328
Stack Init f78b7000 Current f78b6d4c Base f78b7000 Limit f78b4000 Call 0
Priority 0 BasePriority 0 PriorityDecrement 0
ChildEBP RetAddr
f78b6d50 8088d262 intelppm!AcpiC1Idle+0x12
f78b6d54 00000000 nt!KiIdleLoop+0xa

2: kd> .asm no_code_bytes
Assembly options: no_code_bytes

2: kd> uf intelppm!AcpiC1Idle
intelppm!AcpiC1Idle:
f6e73c90 push    ecx
f6e73c91 push    0
f6e73c93 call    intelppm!KeQueryPerformanceCounter (f6e740c6)
f6e73c98 mov     ecx,dword ptr [esp]
f6e73c9b mov     dword ptr [ecx],eax
f6e73c9d mov     dword ptr [ecx+4],edx
f6e73ca0 sti
f6e73ca1 hlt
f6e73ca2 push    0
f6e73ca4 call    intelppm!KeQueryPerformanceCounter (f6e740c6)
f6e73ca9 pop     ecx
f6e73caa mov     dword ptr [ecx+8],eax
f6e73cad mov     dword ptr [ecx+0Ch],edx
f6e73cb0 xor     eax,eax
f6e73cb2 ret

2: kd> uf nt!KiIdleLoop
nt!KiIdleLoop:
8088d258 jmp     nt!KiIdleLoop+0xa (8088d262)

nt!KiIdleLoop+0x2:
8088d25a lea     ecx,[ebx+0EC0h]
8088d260 call    dword ptr [ecx]

nt!KiIdleLoop+0xa:
8088d262 pause
8088d264 sti
8088d265 nop
8088d266 nop
8088d267 cli
8088d268 mov     eax,dword ptr [ebx+0A4Ch]
8088d26e or      eax,dword ptr [ebx+0A88h]
8088d274 or      eax,dword ptr [ebx+0C10h]
8088d27a je      nt!KiIdleLoop+0×37 (8088d28f)

nt!KiIdleLoop+0x24:
8088d27c mov     cl,2
8088d27e call    dword ptr [nt!_imp_HalClearSoftwareInterrupt (808010a8)]
8088d284 lea     ecx,[ebx+120h]
8088d28a call    nt!KiRetireDpcList (80831be8)

nt!KiIdleLoop+0x37:
8088d28f cmp     dword ptr [ebx+128h],0
8088d296 je      nt!KiIdleLoop+0xca (8088d322)

nt!KiIdleLoop+0x44:
8088d29c mov     ecx,1Bh
8088d2a1 call    dword ptr [nt!_imp_KfRaiseIrql (80801100)]
8088d2a7 sti
8088d2a8 mov     edi,dword ptr [ebx+124h]
8088d2ae mov     byte ptr [edi+5Dh],1
8088d2b2 lock bts dword ptr [ebx+0A7Ch],0
8088d2bb jae     nt!KiIdleLoop+0x70 (8088d2c8)

nt!KiIdleLoop+0x65:
8088d2bd lea     ecx,[ebx+0A7Ch]
8088d2c3 call    nt!KefAcquireSpinLockAtDpcLevel (80887fd0)

nt!KiIdleLoop+0x70:
8088d2c8 mov     esi,dword ptr [ebx+128h]
8088d2ce cmp     esi,edi
8088d2d0 je      nt!KiIdleLoop+0xb3 (8088d30b)

nt!KiIdleLoop+0x7a:
8088d2d2 and     dword ptr [ebx+128h],0
8088d2d9 mov     dword ptr [ebx+124h],esi
8088d2df mov     byte ptr [esi+4Ch],2
8088d2e3 and     byte ptr [ebx+0AA3h],0
8088d2ea and     dword ptr [ebx+0A7Ch],0

nt!KiIdleLoop+0x99:
8088d2f1 mov     ecx,1
8088d2f6 call    nt!SwapContext (8088d040)
8088d2fb mov     ecx,2
8088d300 call    dword ptr [nt!_imp_KfLowerIrql (80801104)]
8088d306 jmp     nt!KiIdleLoop+0xa (8088d262)

nt!KiIdleLoop+0xb3:
8088d30b and     dword ptr [ebx+128h],0
8088d312 and     dword ptr [ebx+0A7Ch],0
8088d319 and     byte ptr [edi+5Dh],0
8088d31d jmp     nt!KiIdleLoop+0xa (8088d262)

nt!KiIdleLoop+0xca:
8088d322 cmp     byte ptr [ebx+0AA3h],0
8088d329 je      nt!KiIdleLoop+0x2 (8088d25a)

nt!KiIdleLoop+0xd7:
8088d32f sti
8088d330 lea     ecx,[ebx+120h]
8088d336 call    nt!KiIdleSchedule (808343e6)
8088d33b test    eax,eax
8088d33d mov     esi,eax
8088d33f mov     edi,dword ptr [ebx+12Ch]
8088d345 jne     nt!KiIdleLoop+0x99 (8088d2f1)

nt!KiIdleLoop+0xef:
8088d347 jmp     nt!KiIdleLoop+0xa (8088d262)

In some memory dumps taken when systems or sessions were hanging or very slow for some time we might see Busy System pattern where all processors execute non-idle threads and there are threads in ready queues waiting to be scheduled:

3: kd> !running

System Processors f (affinity mask)
  Idle Processors 0

     Prcb      Current   Next
  0  ffdff120  88cef850            ................
  1  f7727120  8940b7a0            ................
  2  f772f120  8776f020            ................
  3  f7737120  87b25360            ................

3: kd> !ready
Processor 0: Ready Threads at priority 8
    THREAD 88161668  Cid 3d58.43a0  Teb: 7ffdf000 Win32Thread: bc1eba48 READY
    THREAD 882d0020  Cid 1004.0520  Teb: 7ffdf000 Win32Thread: bc230838 READY
    THREAD 88716b40  Cid 2034.241c  Teb: 7ffdd000 Win32Thread: bc11b388 READY
    THREAD 88bf7978  Cid 2444.2564  Teb: 7ffde000 Win32Thread: bc1ccc18 READY
    THREAD 876f7a28  Cid 2308.4bfc  Teb: 7ffdd000 Win32Thread: bc1f7b98 READY
Processor 0: Ready Threads at priority 0
    THREAD 8a3925a8  Cid 0004.0008  Teb: 00000000 Win32Thread: 00000000 READY
Processor 1: Ready Threads at priority 9
    THREAD 87e69db0  Cid 067c.3930  Teb: 7ffdb000 Win32Thread: bc180990 READY
Processor 1: Ready Threads at priority 8
    THREAD 88398c70  Cid 27cc.15b4  Teb: 7ffde000 Win32Thread: bc159ea8 READY
Processor 2: Ready Threads at priority 8
    THREAD 8873cdb0  Cid 4c24.4384  Teb: 7ffdd000 Win32Thread: bc1c9838 READY
    THREAD 89f331e0  Cid 453c.4c68  Teb: 7ffdf000 Win32Thread: bc21dbd0 READY
    THREAD 889a03f0  Cid 339c.2fcc  Teb: 7ffdf000 Win32Thread: bc1cdbe8 READY
    THREAD 87aacdb0  Cid 3b80.4ed0  Teb: 7ffde000 Win32Thread: bc1c5d10 READY
Processor 3: No threads in READY state

Here is another example from busy 8-processor system where only one processor was idle at the time of the bugcheck:

5: kd> !ready
Processor 0: No threads in READY state
Processor 1: No threads in READY state
Processor 2: No threads in READY state
Processor 3: No threads in READY state
Processor 4: No threads in READY state
Processor 5: No threads in READY state
Processor 6: No threads in READY state
Processor 7: No threads in READY state

5: kd> !running

System Processors ff (affinity mask)
  Idle Processors 1

     Prcb      Current   Next
  1  f7727120  8713a5a0            ................
  2  f772f120  86214750            ................
  3  f7737120  86f87020            ................
  4  f773f120  86ffe700            ................
  5  f7747120  86803a90            ................
  6  f774f120  86043db0            ................
  7  f7757120  86bcbdb0            ................

5: kd> !thread 8713a5a0 1f
THREAD 8713a5a0  Cid 4ef4.4f04  Teb: 7ffdd000 Win32Thread: bc423920 RUNNING on processor 1
Not impersonating
DeviceMap                 e44e9a40
Owning Process            864d1d88       Image:         SomeExe.exe
Wait Start TickCount      1415535        Ticks: 0
Context Switch Count      7621092                 LargeStack
UserTime                  00:06:59.218
KernelTime                00:19:26.359
Win32 Start Address BROWSEUI!BrowserProtectedThreadProc (0x75ec1c3f)
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init b68b8a70 Current b68b8c28 Base b68b9000 Limit b68b1000 Call b68b8a7c
Priority 13 BasePriority 13 PriorityDecrement 0
ChildEBP RetAddr
00c1f4fc 773dc4e4 USER32!DispatchHookA+0x35
00c1f528 7739c9c6 USER32!fnHkINLPCWPRETSTRUCTA+0x60
00c1f550 7c828536 USER32!__fnDWORD+0x24
00c1f550 808308f4 ntdll!KiUserCallbackDispatcher+0x2e
b68b8a94 8091d6d1 nt!KiCallUserMode+0x4
b68b8aec bf8a26d3 nt!KeUserModeCallback+0x8f
b68b8b70 bf89dd4d win32k!SfnDWORD+0xb4
b68b8be8 bf89d79d win32k!xxxHkCallHook+0x22c
b68b8c90 bf89da19 win32k!xxxCallHook2+0x245
b68b8cac bf8a137a win32k!xxxCallHook+0x26
b68b8cec bf85af67 win32k!xxxSendMessageTimeout+0x1e3
b68b8d10 bf8c182c win32k!xxxWrapSendMessage+0x1b
b68b8d40 8088978c win32k!NtUserMessageCall+0x9d
b68b8d40 7c8285ec nt!KiFastCallEntry+0xfc
00c1f550 7c828536 ntdll!KiFastSystemCallRet
00c1f57c 7739d1ec ntdll!KiUserCallbackDispatcher+0x2e
00c1f5b8 7738cee9 USER32!NtUserMessageCall+0xc
00c1f5d8 01438f73 USER32!SendMessageA+0x7f

5: kd> !thread 86214750
THREAD 86214750  Cid 0b94.1238  Teb: 7ffdb000 Win32Thread: bc2f5ea8 RUNNING on processor 2
Not impersonating
DeviceMap                 e3482310
Owning Process            85790020       Image:         SomeExe.exe
Wait Start TickCount      1415535        Ticks: 0
Context Switch Count      1745682                 LargeStack
UserTime                  00:01:20.031
KernelTime                00:04:03.484
Win32 Start Address 0x75ec1c3f
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init b4861000 Current b4860558 Base b4861000 Limit b4856000 Call 0
Priority 13 BasePriority 13 PriorityDecrement 0
ChildEBP RetAddr  Args to Child
b4860bd8 bf8da699 8623ebc8 bc2f5ea8 00000000 nt!PsGetThreadProcess
b4860bf4 bf89d6e6 8623ebc8 0010a198 be654f38 win32k!IsRestricted+0x2f
b4860c90 bf89da19 be631660 00000000 00000000 win32k!xxxCallHook2+0x12d
b4860cac bf8a137a 00000000 00000000 00000002 win32k!xxxCallHook+0x26
b4860cec bf85af67 be654f38 0000110a 00000001 win32k!xxxSendMessageTimeout+0x1e3
b4860d10 bf8c182c be654f38 0000110a 00000001 win32k!xxxWrapSendMessage+0x1b
b4860d40 8088978c 00250238 0000110a 00000001 win32k!NtUserMessageCall+0x9d
b4860d40 7c8285ec 00250238 0000110a 00000001 nt!KiFastCallEntry+0xfc
00c1f5fc 00000000 00000000 00000000 00000000 ntdll!KiFastSystemCallRet

5: kd> !thread 86f87020 1f
THREAD 86f87020  Cid 0238.0ae8  Teb: 7ffa5000 Win32Thread: 00000000 RUNNING on processor 3
IRP List:
    86869200: (0006,0094) Flags: 00000900  Mdl: 00000000
    85b2a7f0: (0006,0094) Flags: 00000900  Mdl: 00000000
    86f80a20: (0006,0094) Flags: 00000800  Mdl: 00000000
    85e6af68: (0006,0094) Flags: 00000900  Mdl: 00000000
    892a6c78: (0006,0094) Flags: 00000900  Mdl: 00000000
    85d06070: (0006,0094) Flags: 00000900  Mdl: 00000000
    85da35e0: (0006,0094) Flags: 00000900  Mdl: 00000000
    87216340: (0006,0094) Flags: 00000900  Mdl: 00000000
Not impersonating
DeviceMap                 e1003940
Owning Process            8850e020       Image:         lsass.exe
Wait Start TickCount      1415535        Ticks: 0
Context Switch Count      39608
UserTime                  00:00:01.625
KernelTime                00:00:05.437
Win32 Start Address RPCRT4!ThreadStartRoutine (0x77c7b0f5)
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init f4925000 Current f4924c38 Base f4925000 Limit f4922000 Call 0
Priority 10 BasePriority 9 PriorityDecrement 0
*** ERROR: Module load completed but symbols could not be loaded for SomeDrv.sys
ChildEBP RetAddr
f4924640 80972e8e nt!SePrivilegeCheck+0x24
f4924678 80944aa0 nt!SeSinglePrivilegeCheck+0x3a
f4924770 8088978c nt!NtOpenProcess+0x13a
f4924770 8082eff5 nt!KiFastCallEntry+0xfc
f49247f8 f6037bee nt!ZwOpenProcess+0x11
WARNING: Stack unwind information not available. Following frames may be wrong.
f4924830 f6002996 SomeDrv+0x48bee

5: kd> !thread 86ffe700 1f
THREAD 86ffe700  Cid 1ba4.1ba8  Teb: 7ffdf000 Win32Thread: bc23cea8 RUNNING on processor 4
Not impersonating
DeviceMap                 e44e9a40
Owning Process            87005708       Image:         WINWORD.EXE
Wait Start TickCount      1415535        Ticks: 0
Context Switch Count      1547251                 LargeStack
UserTime                  00:01:00.750
KernelTime                00:00:45.265
*** ERROR: Symbol file could not be found.  Defaulted to export symbols for WINWORD.EXE -
Win32 Start Address WINWORD (0x300019b0)
Start Address kernel32!BaseProcessStartThunk (0x77e617f8)
Stack Init f3465000 Current f3464c48 Base f3465000 Limit f345e000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr
f3464d64 7c8285eb nt!KiFastCallEntry+0x91
f3464d68 badb0d00 ntdll!KiFastSystemCall+0x3

5: kd> !thread 86803a90 1f
THREAD 86803a90  Cid 3c20.29f8  Teb: 7ffdf000 Win32Thread: bc295480 RUNNING on processor 5
Not impersonating
DeviceMap                 e518c6b8
Owning Process            857d5500       Image:         SystemDump.exe
Wait Start TickCount      1415535        Ticks: 0
Context Switch Count      310                 LargeStack
UserTime                  00:00:00.015
KernelTime                00:00:00.046
*** ERROR: Module load completed but symbols could not be loaded for SystemDump.exe
Win32 Start Address SystemDump_400000 (0x0040fe92)
Start Address kernel32!BaseProcessStartThunk (0x77e617f8)
Stack Init b38a4000 Current b38a3c08 Base b38a4000 Limit b389f000 Call 0
Priority 11 BasePriority 8 PriorityDecrement 2
ChildEBP RetAddr  Args to Child
b38a3bf0 f79e3743 000000e2 cccccccc 866962b0 nt!KeBugCheckEx+0x1b
WARNING: Stack unwind information not available. Following frames may be wrong.
b38a3c3c 8081df65 865c4460 870888c0 85a7ff90 SystemDump+0x743
b38a3c50 808f5437 87088930 85a7ff90 870888c0 nt!IofCallDriver+0x45
b38a3c64 808f61bf 865c4460 870888c0 85a7ff90 nt!IopSynchronousServiceTail+0x10b
b38a3d00 808eed08 000000e4 00000000 00000000 nt!IopXxxControlFile+0x5e5
b38a3d34 8088978c 000000e4 00000000 00000000 nt!NtDeviceIoControlFile+0x2a
b38a3d34 7c8285ec 000000e4 00000000 00000000 nt!KiFastCallEntry+0xfc
0012efc4 7c826fcb 77e416f5 000000e4 00000000 ntdll!KiFastSystemCallRet
0012efc8 77e416f5 000000e4 00000000 00000000 ntdll!NtDeviceIoControlFile+0xc
0012f02c 00402208 000000e4 9c400004 00a37b38 kernel32!DeviceIoControl+0x137
0012f884 00404f8e 0012fe80 00000001 00000000 SystemDump_400000+0x2208

5: kd> !thread 86043db0 1f
THREAD 86043db0  Cid 0610.55dc  Teb: 7ffa1000 Win32Thread: 00000000 RUNNING on processor 6
IRP List:
    86dc99a0: (0006,0094) Flags: 00000a00  Mdl: 00000000
Impersonation token:  e7b30030 (Level Impersonation)
DeviceMap                 e4e470a8
Owning Process            891374a8       Image:         SomeSvc.exe
Wait Start TickCount      1415215        Ticks: 320 (0:00:00:05.000)
Context Switch Count      11728
UserTime                  00:00:02.546
KernelTime                00:02:57.765
Win32 Start Address 0x0082b983
LPC Server thread working on message Id 82b983
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init b49c1000 Current b49c0a7c Base b49c1000 Limit b49be000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr
b49c0b80 8087c9c0 hal!KeReleaseQueuedSpinLock+0x2d
b49c0ba0 8087ca95 nt!ExReleaseResourceLite+0xac
b49c0ba4 f6faa5ae nt!ExReleaseResourceAndLeaveCriticalRegion+0x5
b49c0bb8 f6faad05 termdd!_IcaCallStack+0x60
b49c0bdc f6fa6bda termdd!IcaCallDriver+0x71
b49c0c34 f6fa86dc termdd!IcaWriteChannel+0xd8
b49c0c50 f6fa8cc6 termdd!IcaWrite+0x40
b49c0c68 8081df65 termdd!IcaDispatch+0xd0
b49c0c7c 808f5437 nt!IofCallDriver+0x45
b49c0c90 808f3157 nt!IopSynchronousServiceTail+0x10b
b49c0d38 8088978c nt!NtWriteFile+0x663
b49c0d38 7c8285ec nt!KiFastCallEntry+0xfc
0254d814 7c827d3b ntdll!KiFastSystemCallRet
0254d818 77e5b012 ntdll!NtWriteFile+0xc
0254d878 004389f2 kernel32!WriteFile+0xa9

5: kd> !thread 86bcbdb0 1f
THREAD 86bcbdb0  Cid 34ac.1b04  Teb: 7ffdd000 Win32Thread: bc3d9a48 RUNNING on processor 7
IRP List:
    8581d900: (0006,01fc) Flags: 00000884  Mdl: 00000000
Not impersonating
DeviceMap                 e153fc48
Owning Process            872fb708       Image:         SomeExe.exe
Wait Start TickCount      1415535        Ticks: 0
Context Switch Count      7655285                 LargeStack
UserTime                  00:10:09.343
KernelTime                00:30:21.296
Win32 Start Address 0x75ec1c3f
Start Address 0x77e617ec
Stack Init b86cb000 Current b86ca58c Base b86cb000 Limit b86c2000 Call 0
Priority 13 BasePriority 13 PriorityDecrement 0
ChildEBP RetAddr
b86ca974 f724ffc2 fltmgr!FltpPerformPostCallbacks+0x260
b86ca988 f72504f1 fltmgr!FltpProcessIoCompletion+0x10
b86ca998 f7250b83 fltmgr!FltpPassThroughCompletion+0x89
b86ca9c8 f725e5de fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x269
b86caa04 8081df65 fltmgr!FltpCreate+0x26a
b86caa18 f75fa8c7 nt!IofCallDriver+0x45
b86caa40 f75faa5a SomeFlt!PassThrough+0xbb
b86caa5c 8081df65 SomeFlt!Create+0xda
b86caa70 808f8f71 nt!IofCallDriver+0x45
b86cab58 80937942 nt!IopParseDevice+0xa35
b86cabd8 80933a76 nt!ObpLookupObjectName+0x5b0
b86cac2c 808eae25 nt!ObOpenObjectByName+0xea
b86caca8 808ec0bf nt!IopCreateFile+0x447
b86cad04 808efc4f nt!IoCreateFile+0xa3
b86cad44 8088978c nt!NtOpenFile+0x27
b86cad44 7c8285ec nt!KiFastCallEntry+0xfc

Running threads have good chance to be Spiking Threads.

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 13c)

Friday, November 2nd, 2007

Although handle leaks may result in insufficient pool memory, many drivers allocate their own private memory and specify a 4-letter ASCII tag, for example, non-paged pool from my x64 Vista workstation:

lkd> !poolused 3
   Sorting by  NonPaged Pool Consumed

  Pool Used:
            NonPaged
 Tag    Allocs    Frees     Diff     Used
 EtwB      304      134      170  6550080  Etw Buffer , Binary: nt!etw
 File 32630649 32618671    11978  3752928  File objects
 Pool       16       11        5  3363472  Pool tables, etc.
 Ntfr   204791   187152    17639  2258704  ERESOURCE , Binary: ntfs.sys
 FMsl   199039   187685    11354  2179968  STREAM_LIST_CTRL structure , Binary: fltmgr.sys
 MmCa   250092   240351     9741  2134368  Mm control areas for mapped files , Binary: nt!mm
 ViMm   135503   134021     1482  1783824  Video memory manager , Binary: dxgkrnl.sys
 Cont       53       12       41  1567664  Contiguous physical memory allocations for device drivers
 Thre    72558    71527     1031  1234064  Thread objects , Binary: nt!ps
 VoSm      872      851       21  1220544  Bitmap allocations , Binary: volsnap.sys
 NtFs  8122505  8110933    11572  1190960  StrucSup.c , Binary: ntfs.sys
 AmlH        1        0        1  1048576  ACPI AMLI Pooltags
 SaSc    20281    14820     5461  1048512  UNKNOWN pooltag ‘SaSc’, please update pooltag.txt
 RaRS     1000        0     1000   960000  UNKNOWN pooltag ‘RaRS’, please update pooltag.txt


If the pool tag is unknown the following Microsoft article KB298102 explains how to locate the corresponding driver. We can also use memory search in WinDbg to locate kernel space addresses and see what modules they correspond to. 

WinDbg shows the number of failed pool allocations and also shows a message when pool usage is nearly its maximum. Below I put some examples with possible troubleshooting hints.

Session pool

3: kd> !vm

*** Virtual Memory Usage ***
       Physical Memory:     1572637 (   6290548 Kb)
       Page File: \??\C:\pagefile.sys
         Current:   3145728 Kb  Free Space:   3001132 Kb
         Minimum:   3145728 Kb  Maximum:      3145728 Kb
       Available Pages:     1317401 (   5269604 Kb)
       ResAvail Pages:      1478498 (   5913992 Kb)
       Locked IO Pages:         114 (       456 Kb)
       Free System PTEs:     194059 (    776236 Kb)
       Free NP PTEs:          32766 (    131064 Kb)
       Free Special NP:           0 (         0 Kb)
       Modified Pages:          443 (      1772 Kb)
       Modified PF Pages:       442 (      1768 Kb)
       NonPagedPool Usage:    13183 (     52732 Kb)
       NonPagedPool Max:      65215 (    260860 Kb)

       PagedPool 0 Usage:     11328 (     45312 Kb)
       PagedPool 1 Usage:      1473 (      5892 Kb)
       PagedPool 2 Usage:      1486 (      5944 Kb)
       PagedPool 3 Usage:      1458 (      5832 Kb)
       PagedPool 4 Usage:      1505 (      6020 Kb)
       PagedPool Usage:       17250 (     69000 Kb)
       PagedPool Maximum:     65536 (    262144 Kb)

 

       ********** 3441 pool allocations have failed **********
 

       Shared Commit:          8137 (     32548 Kb)
       Special Pool:              0 (         0 Kb)
       Shared Process:         8954 (     35816 Kb)
       PagedPool Commit:      17312 (     69248 Kb)
       Driver Commit:          2095 (      8380 Kb)
       Committed pages:      212476 (    849904 Kb)
       Commit limit:        2312654 (   9250616 Kb)

Paged and non-paged pool usage is far from maximum therefore we check session pool:

3: kd> !vm 4

       Terminal Server Memory Usage By Session:
 

       Session Paged Pool Maximum is 32768K
       Session View Space Maximum is 20480K

 

       Session ID 0 @ f79a1000:
       Paged Pool Usage:        9824K
       Commit Usage:           10148K

 

       Session ID 2 @ f7989000:
       Paged Pool Usage:        1212K
       Commit Usage:            2180K

 

       Session ID 9 @ f79b5000:
       Paged Pool Usage:       32552K

 

       *** 7837 Pool Allocation Failures ***
 

       Commit Usage:           33652K

Here Microsoft article KB840342 might help.

Paged pool

We might have a direct warning:

1: kd> !vm

*** Virtual Memory Usage ***
 Physical Memory:   511881   ( 2047524 Kb)
 Page File: \??\S:\pagefile.sys
    Current:   2098176Kb Free Space:   1837740Kb
    Minimum:   2098176Kb Maximum:      2098176Kb
 Page File: \??\R:\pagefile.sys
    Current:   1048576Kb Free Space:    792360Kb
    Minimum:   1048576Kb Maximum:      1048576Kb
 Available Pages:   201353   (  805412 Kb)
 ResAvail Pages:    426839   ( 1707356 Kb)
 Modified Pages:     45405   (  181620 Kb)
 NonPagedPool Usage: 10042   (   40168 Kb)
 NonPagedPool Max:   68537   (  274148 Kb)
 PagedPool 0 Usage:  26820   (  107280 Kb)
 PagedPool 1 Usage:   1491   (    5964 Kb)
 PagedPool 2 Usage:   1521   (    6084 Kb)
 PagedPool 3 Usage:   1502   (    6008 Kb)
 PagedPool 4 Usage:   1516   (    6064 Kb)
 ********** Excessive Paged Pool Usage *****
 PagedPool Usage:    32850   (  131400 Kb)
 PagedPool Maximum:  40960   (  163840 Kb)
 Shared Commit:      14479   (   57916 Kb)
 Special Pool:           0   (       0 Kb)
 Free System PTEs:  135832   (  543328 Kb)
 Shared Process:     15186   (   60744 Kb)
 PagedPool Commit:   32850   (  131400 Kb)
 Driver Commit:       1322   (    5288 Kb)
 Committed pages:   426786   ( 1707144 Kb)
 Commit limit:     1259456   ( 5037824 Kb)

or if there is no warning we can check the size manually and if paged pool usage is close to its maximum but for non-paged pool it is not then most likely failed allocations were from paged pool:

0: kd> !vm
 

*** Virtual Memory Usage ***
       Physical Memory:     4193696 (  16774784 Kb)
       Page File: \??\C:\pagefile.sys
         Current:   4193280 Kb  Free Space:   3313120 Kb
         Minimum:   4193280 Kb  Maximum:      4193280 Kb
       Available Pages:     3210617 (  12842468 Kb)
       ResAvail Pages:      4031978 (  16127912 Kb)
       Locked IO Pages:         120 (       480 Kb)
       Free System PTEs:      99633 (    398532 Kb)
       Free NP PTEs:          26875 (    107500 Kb)
       Free Special NP:           0 (         0 Kb)
       Modified Pages:          611 (      2444 Kb)
       Modified PF Pages:       590 (      2360 Kb)
       NonPagedPool 0 Used:    8271 (   33084 Kb)
       NonPagedPool 1 Used:   13828 (   55312 Kb)
       NonPagedPool Usage:    37846 (    151384 Kb)
       NonPagedPool Max:      65215 (    260860 Kb)

       PagedPool 0 Usage:     82308 (    329232 Kb)
       PagedPool 1 Usage:     12700 (     50800 Kb)
       PagedPool 2 Usage:     25702 (    102808 Kb)
       PagedPool Usage:      120710 (    482840 Kb)
       PagedPool Maximum:    134144 (    536576 Kb)

 

      ********** 818 pool allocations have failed **********
 

       Shared Commit:         80168 (    320672 Kb)
       Special Pool:              0 (         0 Kb)
       Shared Process:        55654 (    222616 Kb)
       PagedPool Commit:     120772 (    483088 Kb)
       Driver Commit:          1890 (      7560 Kb)
       Committed pages:     1344388 (   5377552 Kb)
       Commit limit:        5177766 (  20711064 Kb)

!poolused 4 WinDbg command will sort paged pool consumption by pool tag:

0: kd> !poolused 4
   Sorting by  Paged Pool Consumed

 

  Pool Used:
            NonPaged            Paged
 Tag    Allocs     Used    Allocs     Used
 MmSt        0        0     85622 140642616     Mm section object prototype ptes , Binary: nt!mm
 Ntff        5     1040     63715 51991440      FCB_DATA , Binary: ntfs.sys

Here Microsoft article KB312362 might help.

Non-paged pool

0: kd> !vm
 

*** Virtual Memory Usage ***
       Physical Memory:      851775 (   3407100 Kb)
       Page File: \??\C:\pagefile.sys
         Current:   4190208 Kb  Free Space:   4175708 Kb
         Minimum:   4190208 Kb  Maximum:      4190208 Kb
       Available Pages:      147274 (    589096 Kb)
       ResAvail Pages:       769287 (   3077148 Kb)
       Locked IO Pages:         118 (       472 Kb)
       Free System PTEs:     184910 (    739640 Kb)
       Free NP PTEs:            110 (       440 Kb)
       Free Special NP:           0 (         0 Kb)
       Modified Pages:          168 (       672 Kb)
       Modified PF Pages:       168 (       672 Kb)
       NonPagedPool Usage:    64445 (    257780 Kb)
       NonPagedPool Max:      64640 (    258560 Kb)
       ********** Excessive NonPaged Pool Usage *****
       PagedPool 0 Usage:     21912 (     87648 Kb)
       PagedPool 1 Usage:       691 (      2764 Kb)
       PagedPool 2 Usage:       706 (      2824 Kb)
       PagedPool 3 Usage:       704 (      2816 Kb)
       PagedPool 4 Usage:       708 (      2832 Kb)
       PagedPool Usage:       24721 (     98884 Kb)
       PagedPool Maximum:    134144 (    536576 Kb)

 

       ********** 429 pool allocations have failed **********
 

       Shared Commit:          5274 (     21096 Kb)
       Special Pool:              0 (         0 Kb)
       Shared Process:         3958 (     15832 Kb)
       PagedPool Commit:      24785 (     99140 Kb)
       Driver Commit:         19289 (     77156 Kb)
       Committed pages:      646282 (   2585128 Kb)
       Commit limit:        1860990 (   7443960 Kb)

!poolused 3 WinDbg command will sort non-paged pool consumption by pool tag:

0: kd> !poolused 3
   Sorting by  NonPaged Pool Consumed

 

  Pool Used:
            NonPaged
 Tag    Allocs    Frees     Diff
 Ddk   9074558  3859522  5215036  Default for driver allocated memory (user’s of ntddk.h)
 MmCm    43787    42677     1110  Calls made to MmAllocateContiguousMemory , Binary: nt!mm
 LSwi        1        0        1  initial work context
 TCPt  3281838  3281808       30  TCP/IP network protocol , Binary: TCP

Regarding Ddk tag I published a case study earlier:

The search for ‘Ddk’ tag

The following Microsoft article KB293857 explains how we can use xpool command from old kdex2×86.dll extension which even works for Windows 2003 dumps:

0: kd> !w2kfre\kdex2x86.xpool -map
unable to get NT!MmSizeOfNonPagedMustSucceed location
unable to get NT!MmSubsectionTopPage location
unable to get NT!MmKseg2Frame location
unable to get NT!MmNonPagedMustSucceed location

Status Map of Pool Area Pages
==============================
  'O': one page in use                              ('P': paged out)
  '<': start page of contiguous pages in use        ('{': paged out)
  '>': last page of contiguous pages in use         ('}': paged out)
  '=': intermediate page of contiguous pages in use ('-': paged out)
  '.': one page not used

Non-Paged Pool Area Summary
----------------------------
Maximum Number of Pages  = 64640 pages
Number of Pages In Use   = 36721 pages (56.8%)

          +00000  +08000   +10000  +18000   +20000  +28000   +30000  +38000
82780000: ..OO.OO.OO..O.OO .O..OO.OO.OO..O. OO.O..OO.O..OO.. ..OO.O..OO.OO.OO
827c0000: .O..OO....OO..O. OO.OO.OO....OO.. O....O..OO....OO .O..OO.O..OO..O.
82800000: ..O............. ................ ................ ................
82840000: ................ ................ ................ ................
82880000: ......O.....O... ..O.O.....O..... O.....O.....O... ..O.....O.......
828c0000: ..O.........O... ......OOO.....O. ....O.....O..... O.....O.........
82900000: .O.........OO... O....O........O. ......OO........ OO.O..O.........
82940000: ...............O ..O.OO........OO ................ ...O.....O......
82980000: O.........O..O.. ....O.........O. ........O.....O. ..O.........O...
829c0000: ........O....... ..O...........O. .O..O...O..O.... ..O.........O...
82a00000: ......O..O...... O.........O..... ....O.........O. ................
82a40000: ............O... O..O.O......OO.. ......O.....O... ..O.....O...O.OO
...
...
...
893c0000: ................ ................ ................ ................
89400000: ..........=..=.. ....=.....=..... =..=......=..=.. ....=..=......=.
89440000: ..=............. ............=... =..=.....=..=... =...=.=.....==..
89480000: ....==......=.=. .........=...... ====.=.=........ ................
894c0000: ................ ................ ..........=.=... ...==...........
89500000: ..=............. ..=............. ..=............. ..=.............
89540000: ..=............. ..=............. ..=............. ..=...=.....=..=
89580000: ......=..=...... =..=......=.==== ==..==.=....=... .=....=....=.==.
895c0000: =.....==........ ..=............. =..=......=...=. ................
89600000: ........=...=..= .....=......=..= ==....=......... .........=....=.
89640000: ..=...===...=... ==......=..=..=. ..=..=......=... ......=.=.....=.
...
...
...

Here is another example:

0: kd> !vm

*** Virtual Memory Usage ***
 Physical Memory:   786299   ( 3145196 Kb)
 Page File: \??\C:\pagefile.sys
    Current:   4193280Kb Free Space:   3407908Kb
    Minimum:   4193280Kb Maximum:      4193280Kb
 Available Pages:   200189   (  800756 Kb)
 ResAvail Pages:    657130   ( 2628520 Kb)
 Modified Pages:       762   (    3048 Kb)
 NonPagedPool Usage: 22948   (   91792 Kb)
 NonPagedPool Max:   70145   (  280580 Kb)
 PagedPool 0 Usage:  19666   (   78664 Kb)
 PagedPool 1 Usage:   3358   (   13432 Kb)
 PagedPool 2 Usage:   3306   (   13224 Kb)
 PagedPool 3 Usage:   3312   (   13248 Kb)
 PagedPool 4 Usage:   3309   (   13236 Kb)
 ********** Excessive Paged Pool Usage *****
 PagedPool Usage:    32951   (  131804 Kb)
 PagedPool Maximum:  40960   (  163840 Kb)
 Shared Commit:       9664   (   38656 Kb)
 Special Pool:           0   (       0 Kb)
 Free System PTEs:  103335   (  413340 Kb)
 Shared Process:     45024   (  180096 Kb)
 PagedPool Commit:   32951   (  131804 Kb)
 Driver Commit:       1398   (    5592 Kb)
 Committed pages:   864175   ( 3456700 Kb)
 Commit limit:     1793827   ( 7175308 Kb)

0: kd> !poolused 4
   Sorting by Paged Pool Consumed

  Pool Used:
            NonPaged            Paged
 Tag    Allocs     Used    Allocs     Used
 CM         85     5440     11045 47915424
 MyAV        0        0       186 14391520

 MmSt        0        0     11795 13235744
 Obtb      709    90752      2712 11108352
 Ntff        5     1120      9886  8541504


MyAV tag seems to be the prefix for MyAVDrv module and this is hardly a coincidence. Looking at the list of drivers we see that MyAVDrv.sys was loaded and unloaded several times. Could it be that it didn’t free its non-paged pool allocations?

0: kd> lmv m MyAVDrv.sys
start    end        module name

Unloaded modules:
a5069000 a5084000   MyAVDrv.sys
    Timestamp: unavailable (00000000)
    Checksum:  00000000
a5069000 a5084000   MyAVDrv.sys
    Timestamp: unavailable (00000000)
    Checksum:  00000000
a5069000 a5084000   MyAVDrv.sys
    Timestamp: unavailable (00000000)
    Checksum:  00000000
b93e1000 b93fc000   MyAVDrv.sys
    Timestamp: unavailable (00000000)
    Checksum:  00000000
b9ae5000 b9b00000   MyAVDrv.sys
    Timestamp: unavailable (00000000)
    Checksum:  00000000
be775000 be790000   MyAVDrv.sys
    Timestamp: unavailable (00000000)
    Checksum:  00000000

Also we see that CM tag has the most allocations and !locks command shows hundreds of threads waiting for registry, an example of High Contention pattern:

0: kd> !locks

Resource @ nt!CmpRegistryLock (0x80478b00)    Shared 10 owning threads
    Contention Count = 9149810
    NumberOfSharedWaiters = 718
    NumberOfExclusiveWaiters = 21

Therefore we see at least two problems in this memory dump: excessive paged pool usage and high thread contention around registry resource slowing down if not halting the system. 

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis AntiPatterns (Part 5)

Thursday, November 1st, 2007

Fooled by Description or the first incursion into Psychology of Memory Dump Analysis 

From my observation an engineer with software development background opens a crash dump after glancing at a problem description provided by a customer or even without reading it first. Only if the problem is not immediately obvious from the memory dump file the engineer will read the problem description thoroughly. On the contrary, an engineer with technical support or system administration background will thoroughly read the problem description first. In the latter case the description might influence the direction of analysis.

Here is an example. The description says - slow application start and you have a memory dump from a process. An engineer with technical support background will most likely look for hang patterns inside the dump. An engineer with experience writing native applications in C and C++ will open the dump and check an exception stored in it and if it is a breakpoint the suspicion might arise that the memory dump was taken manually because of the hanging process. Based on analysis the engineer might even correct the problem description or add questions that clarify the discrepancy between what is seen in the dump and what users perceive.

- Dmitry Vostokov @ DumpAnalysis.org -

Patterns on Portal

Wednesday, October 31st, 2007

Some Crash Dump Analysis (CDA) Portal announcements:

  • Registration-free - no need to register. This has been done to remove administration overhead. Thanks for everyone who has registered so far.

  • CDA Patterns are listed on the right side bar. These most popular posts from my blog are made readily accessible:

- Dmitry Vostokov @ DumpAnalysis.org -

Memory Dump - A Mathematical Definition

Wednesday, October 24th, 2007

This is the first post in Science of Memory Dump Analysis category where I apply philosophy, systems theory, mathematics, physics and computer science ideas. It was inspired after reading Life Itself book written by Robert Rosen where computers are depicted as direct sums of states. As shown in that book, in the case of machines, their synthetic models (direct sums) are equivalent to analytic models (direct product of observables). Taking every single bit as an observable having its values in Z2 set {0, 1} we can make a definition of an ideal memory dump as a direct product or a direct sum of bits saved instantaneously at the given time:

i si = i si

Of course, we can also consider bytes having 8 bits as observables having their values from Z256 set, etc.

In our case we can simply rewrite direct sum or product as the list of bits, bytes, words or double words, etc:

(…, si-1, si, si+1, …, sj-1, sj, sj+1, …)

According to Rosen we include hardware states (registers, for example) and partition memory into input, output states for particular computation and other states.

Saving a memory dump takes certain amount of time. Suppose that it takes 3 discrete time events (ticks). During the first tick we save memory up to (…, si-1, si) and that memory has some relationship to sj state. During the second tick sj state changes its value and during the 3rd tick we copy the rest of the memory (si+1, …, sj-1, sj, sj+1, …). Now we see that the final memory dump is inconsistent:

(…, si-1, si, si+1, …, sj-1, sj, sj+1, …)

I explained this earlier in plain words in Inconsistent Dump pattern. Therefore we might consider a real memory dump as a direct sum of disjoint memory areas Mt taken during some time interval (t0, …, tn)

M = t Mt where Mt = k stk or simply

M = t k stk

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 32)

Tuesday, October 23rd, 2007

When we look at a thread and it is not in the Passive Thread list and looks more like Blocked Thread we may ask whether it is Main Thread. Every process has at least one thread of execution called main or primary thread. Most GUI applications have window message processing loop inside their main process thread. When a memory dump is saved it is most likely that this thread is blocked waiting for window or user-defined messages to arrive and can be considered as Passive Thread. If we see it blocked on something else waiting for some time we may consider that the application was hanging. 

Here is an example of the normal iexplore.exe thread stack taken from a kernel dump:

PROCESS 88de4140  SessionId: 3  Cid: 15a8    Peb: 7ffdf000  ParentCid: 0e28
    DirBase: 0a43df40  ObjectTable: 88efe008  TableSize: 852.
    Image: IEXPLORE.EXE
    VadRoot 88dbbca8 Clone 0 Private 6604. Modified 951. Locked 0.
    DeviceMap 88de6408
    Token                             e3f5ccf0
    ElapsedTime                        0:10:52.0281
    UserTime                          0:00:06.0250
    KernelTime                        0:00:10.0421
    QuotaPoolUsage[PagedPool]         126784
    QuotaPoolUsage[NonPagedPool]      197704
    Working Set Sizes (now,min,max)  (8347, 50, 345) (33388KB, 200KB, 1380KB)
    PeakWorkingSetSize                10000
    VirtualSize                       280 Mb
    PeakVirtualSize                   291 Mb
    PageFaultCount                    15627
    MemoryPriority                    FOREGROUND
    BasePriority                      8
    CommitCharge                      7440

THREAD 88ee2b00  Cid 15a8.1654  Teb: 7ffde000  Win32Thread: a2242018 WAIT: (WrUserRequest) UserMode Non-Alertable
    88f82ee0  SynchronizationEvent
Not impersonating
Owning Process 88de4140
Wait Start TickCount    104916        Elapsed Ticks: 0
Context Switch Count    100208                   LargeStack
UserTime                  0:00:04.0484
KernelTime                0:00:09.0859
Start Address KERNEL32!BaseProcessStartThunk (0x7c57b70c)
Stack Init be597000 Current be596cc8 Base be597000 Limit be58f000 Call 0
Priority 12 BasePriority 8 PriorityDecrement 0 DecrementCount 0

ChildEBP RetAddr
be596ce0 8042d8d7 nt!KiSwapThread+0x1b1
be596d08 a00019c2 nt!KeWaitForSingleObject+0x1a3
be596d44 a00138c5 win32k!xxxSleepThread+0x18a
be596d54 a00138d1 win32k!xxxWaitMessage+0xe
be596d5c 8046b2a9 win32k!NtUserWaitMessage+0xb
be596d5c 77e3c7cd nt!KiSystemService+0xc9

In the same kernel dump there is another iexplore.exe process with the following main thread stack which had been blocked for 31 seconds:

PROCESS 8811ca00  SessionId: 21  Cid: 4d18    Peb: 7ffdf000  ParentCid: 34c8
    DirBase: 0a086ee0  ObjectTable: 87d07528  TableSize: 677.
    Image: IEXPLORE.EXE
    VadRoot 87a92ae8 Clone 0 Private 4600. Modified 227. Locked 0.
    DeviceMap 88b174e8
    Token                             e49508d0
    ElapsedTime                        0:08:03.0062
    UserTime                          0:00:01.0531
    KernelTime                        0:00:10.0375
    QuotaPoolUsage[PagedPool]         120792
    QuotaPoolUsage[NonPagedPool]      198376
    Working Set Sizes (now,min,max)  (7726, 50, 345) (30904KB, 200KB, 1380KB)
    PeakWorkingSetSize                7735
    VirtualSize                       272 Mb
    PeakVirtualSize                   275 Mb
    PageFaultCount                    11688
    MemoryPriority                    BACKGROUND
    BasePriority                      8
    CommitCharge                      6498

THREAD 87ce6da0  Cid 4d18.4c68  Teb: 7ffde000  Win32Thread: a22157b8 WAIT: (Executive) KernelMode Non-Alertable
    b5bd6370  NotificationEvent
IRP List:
    885d4808: (0006,00dc) Flags: 00000014  Mdl: 00000000
Not impersonating
Owning Process 8811ca00
Wait Start TickCount    102908        Elapsed Ticks: 2008
Context Switch Count    130138                   LargeStack
UserTime                  0:00:01.0125
KernelTime                0:00:08.0843
Start Address KERNEL32!BaseProcessStartThunk (0×7c57b70c)
Stack Init b5bd7000 Current b5bd62f4 Base b5bd7000 Limit b5bcf000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 0

ChildEBP RetAddr
b5bd630c 8042d8d7 nt!KiSwapThread+0x1b1
b5bd6334 bf09342d nt!KeWaitForSingleObject+0x1a3
b5bd6380 bf08896f mrxsmb!SmbCeAssociateExchangeWithMid+0x24b
b5bd63b0 bf0aa0ef mrxsmb!SmbCeTranceive+0xff
b5bd6490 bf0a92df mrxsmb!SmbTransactExchangeStart+0x559
b5bd64a8 bf0a9987 mrxsmb!SmbCeInitiateExchange+0x2ac
b5bd64c4 bf0a96e2 mrxsmb!SmbCeSubmitTransactionRequest+0x124
b5bd6524 bf0ac7c3 mrxsmb!_SmbCeTransact+0x86
b5bd6608 bf104ea0 mrxsmb!MRxSmbQueryFileInformation+0x553
b5bd66b4 bf103aff rdbss!__RxInitializeTopLevelIrpContext+0x52
b5bd6784 bf10da73 rdbss!WPP_SF_ZL+0x4b
b5bd67b4 bf0a8b29 rdbss!RxCleanupPipeQueues+0x117
b5bd67d4 8041ef05 mrxsmb!MRxSmbFsdDispatch+0x118
b5bd67e8 eb833839 nt!IopfCallDriver+0x35
b5bd6890 804a8109 nt!IopQueryXxxInformation+0x164
b5bd68b0 804c7d63 nt!IoQueryFileInformation+0x19
b5bd6a4c 80456562 nt!IopParseDevice+0xe8f
b5bd6ac4 804de0c0 nt!ObpLookupObjectName+0x504
b5bd6bd4 804a929b nt!ObOpenObjectByName+0xc8
b5bd6d54 8046b2a9 nt!NtQueryFullAttributesFile+0xe7
b5bd6d54 77f88887 nt!KiSystemService+0xc9

0: kd> !whattime 0n2008
2008 Ticks in Standard Time: 31.375s

Main thread need not be GUI thread. Most input console applications have ReadConsole calls in normal main process thread stack:

0:000> kL
ChildEBP RetAddr
0012fc6c 77d20190 ntdll!KiFastSystemCallRet
0012fc70 77d27fdf ntdll!NtRequestWaitReplyPort+0xc
0012fc90 765d705c ntdll!CsrClientCallServer+0xc2
0012fd8c 76634674 kernel32!ReadConsoleInternal+0x1cd
0012fe14 765eaf6a kernel32!ReadConsoleA+0×40
0012fe7c 6ec35196 kernel32!ReadFile+0×84
0012fec0 6ec35616 MSVCR80!_read_nolock+0×201
0012ff04 6ec45928 MSVCR80!_read+0xc0
0012ff1c 6ec49e47 MSVCR80!_filbuf+0×78
0012ff54 0040100d MSVCR80!getc+0×113
0012ff5c 0040117c ConsoleTest!wmain+0xd
0012ffa0 765d3833 ConsoleTest!__tmainCRTStartup+0×10f
0012ffac 77cfa9bd kernel32!BaseThreadInitThunk+0xe
0012ffec 00000000 ntdll!_RtlUserThreadStart+0×23

0:000> kL
ChildEBP RetAddr
001cf594 77d20190 ntdll!KiFastSystemCallRet
001cf598 77d27fdf ntdll!NtRequestWaitReplyPort+0xc
001cf5b8 765d705c ntdll!CsrClientCallServer+0xc2
001cf6b4 765d6efe kernel32!ReadConsoleInternal+0x1cd
001cf740 49ecd538 kernel32!ReadConsoleW+0×47
001cf7a8 49ecd645 cmd!ReadBufFromConsole+0xb5
001cf7d4 49ec2247 cmd!FillBuf+0×175
001cf7d8 49ec2165 cmd!GetByte+0×11
001cf7f4 49ec20d8 cmd!Lex+0×75
001cf80c 49ec207f cmd!GeToken+0×27
001cf81c 49ec200a cmd!ParseStatement+0×36
001cf830 49ec6038 cmd!Parser+0×46
001cf878 49ecc703 cmd!main+0×1de
001cf8bc 765d3833 cmd!_initterm_e+0×163
001cf8c8 77cfa9bd kernel32!BaseThreadInitThunk+0xe
001cf908 00000000 ntdll!_RtlUserThreadStart+0×23

- Dmitry Vostokov @ DumpAnalysis.org -

The search for ‘Ddk’ tag

Monday, October 22nd, 2007

Sometimes we get pool allocation failures and the driver’s tag is ‘Ddk’:

0: kd> !vm

*** Virtual Memory Usage ***
 Physical Memory:      851775 (   3407100 Kb)
 Page File: \??\C:\pagefile.sys
   Current:   4190208 Kb  Free Space:   4175708 Kb
   Minimum:   4190208 Kb  Maximum:      4190208 Kb
 Available Pages:      147274 (    589096 Kb)
 ResAvail Pages:       769287 (   3077148 Kb)
 Locked IO Pages:         118 (       472 Kb)
 Free System PTEs:     184910 (    739640 Kb)
 Free NP PTEs:            110 (       440 Kb)
 Free Special NP:           0 (         0 Kb)
 Modified Pages:          168 (       672 Kb)
 Modified PF Pages:       168 (       672 Kb)
 NonPagedPool Usage:    64445 (    257780 Kb)
 NonPagedPool Max:      64640 (    258560 Kb)
 ********** Excessive NonPaged Pool Usage *****

 PagedPool 0 Usage:     21912 (     87648 Kb)
 PagedPool 1 Usage:       691 (      2764 Kb)
 PagedPool 2 Usage:       706 (      2824 Kb)
 PagedPool 3 Usage:       704 (      2816 Kb)
 PagedPool 4 Usage:       708 (      2832 Kb)
 PagedPool Usage:       24721 (     98884 Kb)
 PagedPool Maximum:    134144 (    536576 Kb)

 ********** 429 pool allocations have failed **********

 Shared Commit:          5274 (     21096 Kb)
 Special Pool:              0 (         0 Kb)
 Shared Process:         3958 (     15832 Kb)
 PagedPool Commit:      24785 (     99140 Kb)
 Driver Commit:         19289 (     77156 Kb)
 Committed pages:      646282 (   2585128 Kb)
 Commit limit:        1860990 (   7443960 Kb)

0: kd> !poolused 3
   Sorting by  NonPaged Pool Consumed

  Pool Used:
            NonPaged
 Tag    Allocs    Frees     Diff     Used
 Ddk   9074558  3859522  5215036 225708304 Default for driver allocated memory (user’s of ntddk.h)

How do we find which driver had caused this memory leak? We can search for drivers using the following command:

C:\>findstr /S /m /l hDdk *.sys  

or we can guess the driver using the fact that long time ago ExAllocatePool was defined as ExAllocatePoolWithTag(, … ‘Ddk ‘). Currently all DDK samples use their separate driver tags and ExAllocatePool uses ‘None’:

0: kd> .asm no_code_bytes
Assembly options: no_code_bytes

0: kd> uf ExAllocatePool
nt!ExAllocatePool:
80894d1f mov     edi,edi
80894d21 push    ebp
80894d22 mov     ebp,esp
80894d24 push    656E6F4Eh
80894d29 push    dword ptr [ebp+0Ch]
80894d2c push    dword ptr [ebp+8]
80894d2f call    nt!ExAllocatePoolWithTag (8089b93f)
80894d34 pop     ebp
80894d35 ret     8

0: kd> .formats 656E6F4Eh
Evaluate expression:
  Hex:     656e6f4e
  Decimal: 1701736270
  Octal:   14533467516
  Binary:  01100101 01101110 01101111 01001110
  Chars:   enoN
  Time:    Tue Dec 05 00:31:10 2023
  Float:   low 7.03735e+022 high 0
  Double:  8.40769e-315

Note: we push ‘None’ but see ‘enoN’ in memory because of little endian byte ordering.

Most of the recent drivers use their own tags and it is common not to encounter ‘None’ at all:

kd> !poolused
   Sorting by  Tag

  Pool Used:
            NonPaged            Paged
 Tag    Allocs     Used    Allocs     Used
...
...
...
 None        0        0         1     8192 call to ExAllocatePool

Therefore the driver must be old and if we see most drivers dated 2006-2007 and some dated 1998-2001 the chances are that 2001 drivers were responsible for our memory leak:

b9840000 b9842980   newdriver     Sat Feb 10 00:33:41 2007 (45CD12E5)
b8cfa000 b8d39e00   olddriver     Tue Aug 21 12:18:35 2001 (3B82438B)
f79e5000 f79e6400   veryolddriver Wed Sep 23 13:09:52 1998 (3608E510)

However veryolddriver.sys doesn’t use ExAllocatePoolWithTag so olddriver.sys is under suspicion:

0: kd> !dh f79e5000
...
...
...
     A00 [      33] address [size] of Export Directory
     C00 [      3C] address [size] of Import Directory
     E00 [     3A4] address [size] of Resource Directory
       0 [       0] address [size] of Exception Directory
       0 [       0] address [size] of Security Directory
    1200 [      34] address [size] of Base Relocation Directory
     440 [      54] address [size] of Debug Directory
       0 [       0] address [size] of Description Directory
       0 [       0] address [size] of Special Directory
       0 [       0] address [size] of Thread Storage Directory
       0 [       0] address [size] of Load Configuration Directory
       0 [       0] address [size] of Bound Import Directory
     400 [      34] address [size] of Import Address Table Directory
       0 [       0] address [size] of Delay Import Directory
       0 [       0] address [size] of COR20 Header Directory
       0 [       0] address [size] of Reserved Directory


0: kd> dds f79e5000+400
f79e5400  80a82264 hal!HalTranslateBusAddress
f79e5404  80a84358 hal!READ_PORT_BUFFER_UCHAR
f79e5408  00000000
f79e540c  80840bd9 nt!IofCompleteRequest
f79e5410  808e8f01 nt!IoCreateSymbolicLink
f79e5414  80838035 nt!RtlInitUnicodeString
f79e5418  808fbe85 nt!IoDeleteSymbolicLink
f79e541c  80816a6e nt!MmUnmapIoSpace
f79e5420  808ef1f1 nt!IoCreateDevice
f79e5424  80837e3a nt!READ_REGISTER_BUFFER_UCHAR
f79e5428  80815fc8 nt!IoDeleteDevice
f79e542c  80816814 nt!MmMapIoSpace
f79e5430  00000000
f79e5434  00000000

To confirm that olddriver.sys uses ‘Ddk ‘ tag we can search its address space for code that calls ExAllocatePoolWithTag:

b8cfa000 b8d39e00 olddriver Tue Aug 21 12:18:35 2001 (3B82438B)

0: kd> !dh b8cfa000
...
...
...
       0 [       0] address [size] of Export Directory
   3D330 [      50] address [size] of Import Directory
   3DE00 [     380] address [size] of Resource Directory
       0 [       0] address [size] of Exception Directory
   3FE00 [      88] address [size] of Security Directory
   3E180 [    1BE8] address [size] of Base Relocation Directory
   3B640 [      1C] address [size] of Debug Directory
       0 [       0] address [size] of Description Directory
       0 [       0] address [size] of Special Directory
       0 [       0] address [size] of Thread Storage Directory
       0 [       0] address [size] of Load Configuration Directory
       0 [       0] address [size] of Bound Import Directory
   3B480 [     1B4] address [size] of Import Address Table Directory
       0 [       0] address [size] of Delay Import Directory
       0 [       0] address [size] of COR20 Header Directory
       0 [       0] address [size] of Reserved Directory


0: kd> dds b8cfa000+3B480 b8cfa000+3B480+1B4
b8d35480  80a83dba hal!KeQueryPerformanceCounter
b8d35484  80a7e3c0 hal!KfAcquireSpinLock
b8d35488  80a7e440 hal!KfReleaseSpinLock
b8d3548c  00000000
...
...
...
b8d35544  80812b1a nt!IoWriteErrorLogEntry
b8d35548  8081287b nt!IoAllocateErrorLogEntry
b8d3554c  8082f12f nt!swprintf
b8d35550  8089b93f nt!ExAllocatePoolWithTag
b8d35554  8087c465 nt!KeBugCheckEx
b8d35558  80815407 nt!wcsncat
b8d3555c  8083bc54 nt!ZwQueryValueKey
b8d35560  8083affb nt!ZwClose
b8d35564  80841a14 nt!_wcsicmp
b8d35568  80928d30 nt!ObReferenceObjectByHandle


… 

0: kd> s-d b8cfa000 b8d39e00 b8d35550
b8d19f08  b8d35550 555425ff 25ffb8d3 b8d35480  PU…%TU…%.T..
b8d1a068  b8d35550 ff85f88b 75fc7d89 b85e5f0c  PU…….}.u._^.
b8d2c4e4  b8d35550 0375c085 89c35d5e 04c08330  PU….u.^]..0…

0: kd> u b8d19f08-2
olddriver!ExAllocatePoolWithTag:
b8d19f06 jmp     dword ptr [olddriver!_imp__ExAllocatePoolWithTag (b8d35550)]

0: kd> u b8d2c4e4-2
olddriver!malloc+0x12
b8d2c4e2 call    dword ptr [olddriver!_imp__ExAllocatePoolWithTag (b8d35550)]
b8d2c4e8 test    eax,eax
b8d2c4ea jne     olddriver!malloc+0x1f (b8d2c4ef)
b8d2c4ec pop     esi
b8d2c4ed pop     ebp
b8d2c4ee ret
b8d2c4ef mov     dword ptr [eax],esi
b8d2c4f1 add     eax,4

0: kd> ub b8d1a068-2
olddriver!TraceRoutine+0xc1
b8d1a051 mov     esp,ebp
b8d1a053 pop     ebp
b8d1a054 ret
b8d1a055 cmp     edi,8
b8d1a058 jbe     olddriver!TraceRoutine+0x157 (b8d1a0e7)
b8d1a05e push    206b6444h
b8d1a063 push    edx
b8d1a064 push    0

0: kd> .formats 206b6444
Evaluate expression:
  Hex:     206b6444
  Decimal: 543908932
  Octal:   04032662104
  Binary:  00100000 01101011 01100100 01000100
  Chars:    kdD
  Time:    Sat Mar 28 05:48:52 1987
  Float:   low 1.99384e-019 high 0
  Double:  2.68727e-315

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 31)

Wednesday, October 17th, 2007

When trying to understand why the particular application or service hangs we look at Stack Trace Collection and hope to find some suspicious threads that are waiting for a response. These are active blocked threads. Other threads may appear waiting but they are merely waiting for some notification or data which may or may not come during their lifetime and, therefore, are normal. In other words, they are passive and hence the name of the pattern Passive Thread. Typical examples from user space include

  • - the main service thread and dispatch threads (when idle)

  • - a thread waiting for file or registry notifications

  • - a generic RPC/LPC/COM thread waiting for messages

  • - worker threads waiting for a data to appear in a queue

  • - window message loops (when idle)

  • - socket and network protocol threads (when idle)

  • - a thread with function names on its stack trace suggesting that it is a notification or listener thread

Of course, sometimes these passive threads can be the reason for an application or service hang, but from my experience, most of the time they are not, unless there are other threads which they block. Let’s now look at example stack traces.

Note: Generic threads spawned to service various requests and waiting for data to arrive can be filtered using !uniqstack WinDbg command. Conceptually these threads are part of the so called thread pool software design pattern.

LPC/RPC/COM threads waiting for requests:

  70  Id: 8f8.1100 Suspend: 1 Teb: 7ff80000 Unfrozen
ChildEBP RetAddr
0d82fe18 7c82783b ntdll!KiFastSystemCallRet
0d82fe1c 77c885ac ntdll!NtReplyWaitReceivePortEx+0xc
0d82ff84 77c88792 rpcrt4!LRPC_ADDRESS::ReceiveLotsaCalls+0x198
0d82ff8c 77c8872d rpcrt4!RecvLotsaCallsWrapper+0xd
0d82ffac 77c7b110 rpcrt4!BaseCachedThreadRoutine+0x9d
0d82ffb8 77e64829 rpcrt4!ThreadStartRoutine+0x1b
0d82ffec 00000000 kernel32!BaseThreadStart+0x34

  71  Id: 8f8.1e44 Suspend: 1 Teb: 7ffde000 Unfrozen
ChildEBP RetAddr
0c01fe18 7c82783b ntdll!KiFastSystemCallRet
0c01fe1c 77c885ac ntdll!NtReplyWaitReceivePortEx+0xc
0c01ff84 77c88792 rpcrt4!LRPC_ADDRESS::ReceiveLotsaCalls+0x198
0c01ff8c 77c8872d rpcrt4!RecvLotsaCallsWrapper+0xd
0c01ffac 77c7b110 rpcrt4!BaseCachedThreadRoutine+0x9d
0c01ffb8 77e64829 rpcrt4!ThreadStartRoutine+0x1b
0c01ffec 00000000 kernel32!BaseThreadStart+0x34

  72  Id: 8f8.1804 Suspend: 1 Teb: 7ff90000 Unfrozen
ChildEBP RetAddr
0e22fe18 7c82783b ntdll!KiFastSystemCallRet
0e22fe1c 77c885ac ntdll!NtReplyWaitReceivePortEx+0xc
0e22ff84 77c88792 rpcrt4!LRPC_ADDRESS::ReceiveLotsaCalls+0x198
0e22ff8c 77c8872d rpcrt4!RecvLotsaCallsWrapper+0xd
0e22ffac 77c7b110 rpcrt4!BaseCachedThreadRoutine+0x9d
0e22ffb8 77e64829 rpcrt4!ThreadStartRoutine+0x1b
0e22ffec 00000000 kernel32!BaseThreadStart+0x34

  73  Id: 8f8.1860 Suspend: 1 Teb: 7ff79000 Unfrozen
ChildEBP RetAddr
0da2fe18 7c82783b ntdll!KiFastSystemCallRet
0da2fe1c 77c885ac ntdll!NtReplyWaitReceivePortEx+0xc
0da2ff84 77c88792 rpcrt4!LRPC_ADDRESS::ReceiveLotsaCalls+0x198
0da2ff8c 77c8872d rpcrt4!RecvLotsaCallsWrapper+0xd
0da2ffac 77c7b110 rpcrt4!BaseCachedThreadRoutine+0x9d
0da2ffb8 77e64829 rpcrt4!ThreadStartRoutine+0x1b
0da2ffec 00000000 kernel32!BaseThreadStart+0x34

  74  Id: 8f8.f24 Suspend: 1 Teb: 7ff7e000 Unfrozen
ChildEBP RetAddr
0d20feac 7c8277db ntdll!KiFastSystemCallRet
0d20feb0 77e5bea2 ntdll!ZwRemoveIoCompletion+0xc
0d20fedc 77c7b900 kernel32!GetQueuedCompletionStatus+0x29
0d20ff18 77c7b703 rpcrt4!COMMON_ProcessCalls+0xa1
0d20ff84 77c7b9b5 rpcrt4!LOADABLE_TRANSPORT::ProcessIOEvents+0x117
0d20ff8c 77c8872d rpcrt4!ProcessIOEventsWrapper+0xd
0d20ffac 77c7b110 rpcrt4!BaseCachedThreadRoutine+0x9d
0d20ffb8 77e64829 rpcrt4!ThreadStartRoutine+0x1b
0d20ffec 00000000 kernel32!BaseThreadStart+0x34

  75  Id: 8f8.11f8 Suspend: 1 Teb: 7ffa1000 Unfrozen
ChildEBP RetAddr
08e0feac 7c8277db ntdll!KiFastSystemCallRet
08e0feb0 77e5bea2 ntdll!ZwRemoveIoCompletion+0xc
08e0fedc 77c7b900 kernel32!GetQueuedCompletionStatus+0x29
08e0ff18 77c7b703 rpcrt4!COMMON_ProcessCalls+0xa1
08e0ff84 77c7b9b5 rpcrt4!LOADABLE_TRANSPORT::ProcessIOEvents+0x117
08e0ff8c 77c8872d rpcrt4!ProcessIOEventsWrapper+0xd
08e0ffac 77c7b110 rpcrt4!BaseCachedThreadRoutine+0x9d
08e0ffb8 77e64829 rpcrt4!ThreadStartRoutine+0x1b
08e0ffec 00000000 kernel32!BaseThreadStart+0x34

   2  Id: ecc.c94 Suspend: 1 Teb: 7efac000 Unfrozen
ChildEBP RetAddr
0382f760 76e31330 ntdll!NtDelayExecution+0x15
0382f7c8 76e30dac kernel32!SleepEx+0x62
0382f7d8 75ec40f4 kernel32!Sleep+0xf
0382f7e4 75eafc0d ole32!CROIDTable::WorkerThreadLoop+0x14
0382f800 75eafc73 ole32!CRpcThread::WorkerLoop+0x26
0382f80c 76ea19f1 ole32!CRpcThreadCache::RpcWorkerThreadEntry+0x20
0382f818 7797d109 kernel32!BaseThreadInitThunk+0xe
0382f858 00000000 ntdll!_RtlUserThreadStart+0x23

Worker threads waiting for data items to process:

  43  Id: 8f8.17c0 Suspend: 1 Teb: 7ff8c000 Unfrozen
ChildEBP RetAddr
0c64ff20 7c8277db ntdll!KiFastSystemCallRet
0c64ff24 77e5bea2 ntdll!ZwRemoveIoCompletion+0xc
0c64ff50 67823549 kernel32!GetQueuedCompletionStatus+0x29
0c64ff84 77bcb530 component!WorkItemThread+0×1a9
0c64ffb8 77e64829 msvcrt!_endthreadex+0xa3
0c64ffec 00000000 kernel32!BaseThreadStart+0×34

  44  Id: 8f8.7b4 Suspend: 1 Teb: 7ff8b000 Unfrozen
ChildEBP RetAddr
0c77ff20 7c8277db ntdll!KiFastSystemCallRet
0c77ff24 77e5bea2 ntdll!ZwRemoveIoCompletion+0xc
0c77ff50 67823549 kernel32!GetQueuedCompletionStatus+0x29
0c77ff84 77bcb530 component!WorkItemThread+0×1a9
0c77ffb8 77e64829 msvcrt!_endthreadex+0xa3
0c77ffec 00000000 kernel32!BaseThreadStart+0×34

  45  Id: 8f8.1708 Suspend: 1 Teb: 7ff8a000 Unfrozen
ChildEBP RetAddr
0c87ff20 7c8277db ntdll!KiFastSystemCallRet
0c87ff24 77e5bea2 ntdll!ZwRemoveIoCompletion+0xc
0c87ff50 67823549 kernel32!GetQueuedCompletionStatus+0x29
0c87ff84 77bcb530 component!WorkItemThread+0×1a9
0c87ffb8 77e64829 msvcrt!_endthreadex+0xa3
0c87ffec 00000000 kernel32!BaseThreadStart+0×34

   5 Id: 11fc.16f4 Suspend: 1 Teb: 7ffd9000 Unfrozen
ChildEBP RetAddr
0109bf10 7c822124 ntdll!KiFastSystemCallRet
0109bf14 77e6baa8 ntdll!NtWaitForSingleObject+0xc
0109bf84 77e6ba12 kernel32!WaitForSingleObjectEx+0xac
0109bf98 66886519 kernel32!WaitForSingleObject+0x12
0109ff84 77bcb530 component!WorkerThread+0xe8
0109ffb8 77e66063 msvcrt!_endthreadex+0xa3
0109ffec 00000000 kernel32!BaseThreadStart+0x34

A thread waiting for registry change notification: 

   1  Id: 13c4.350 Suspend: 1 Teb: 000007ff`fffde000 Unfrozen
Child-SP          RetAddr           Call Site
00000000`0012fdd8 000007fe`fd62c361 ntdll!ZwNotifyChangeKey+0xa
00000000`0012fde0 00000001`40001181 ADVAPI32!RegNotifyChangeKeyValue+0×115
00000000`0012ff30 00000000`76d9cdcd sample12!WaitForRegChange+0xe
00000000`0012ff60 00000000`76eec6e1 kernel32!BaseThreadInitThunk+0xd
00000000`0012ff90 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

Idle main service thread and service dispatch threads:

.  0  Id: 65c.660 Suspend: 1 Teb: 000007ff`fffdc000 Unfrozen
Child-SP          RetAddr           Call Site
00000000`0011f2c8 00000000`76d926da ntdll!NtReadFile+0xa
00000000`0011f2d0 000007fe`fd6665aa kernel32!ReadFile+0x8a
00000000`0011f360 000007fe`fd6662e3 ADVAPI32!ScGetPipeInput+0x4a
00000000`0011f440 000007fe`fd6650f3 ADVAPI32!ScDispatcherLoop+0x9a
00000000`0011f540 00000000`ff0423a3 ADVAPI32!StartServiceCtrlDispatcherW+0x176
00000000`0011f7e0 00000000`ff042e66 spoolsv!main+0x23
00000000`0011f850 00000000`76eec6e1 kernel32!BaseThreadInitThunk+0xd
00000000`0011f880 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

   1  Id: 65c.664 Suspend: 1 Teb: 000007ff`fffda000 Unfrozen
Child-SP          RetAddr           Call Site
00000000`0009f9c8 00000000`76d9d820 ntdll!NtWaitForSingleObject+0xa
00000000`0009f9d0 00000000`ff04307f kernel32!WaitForSingleObjectEx+0x9c
00000000`0009fa90 000007fe`fd664bf5 spoolsv!SPOOLER_main+0x80
00000000`0009fac0 00000000`76d9cdcd ADVAPI32!ScSvcctrlThreadW+0x25
00000000`0009faf0 00000000`76eec6e1 kernel32!BaseThreadInitThunk+0xd
00000000`0009fb20 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

Idle window message loops:

  10  Id: 65c.514 Suspend: 1 Teb: 000007ff`fffa2000 Unfrozen
Child-SP          RetAddr           Call Site
00000000`02c5fc18 00000000`76cae6ea USER32!ZwUserGetMessage+0xa
00000000`02c5fc20 000007fe`f88523f0 USER32!GetMessageW+0×34
00000000`02c5fc50 00000000`76d9cdcd usbmon!CPNPNotifications::WindowMessageThread+0×1a0
00000000`02c5fd20 00000000`76eec6e1 kernel32!BaseThreadInitThunk+0xd
00000000`02c5fd50 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

  11  Id: 65c.9bc Suspend: 1 Teb: 000007ff`fffa0000 Unfrozen
Child-SP          RetAddr           Call Site
00000000`037cf798 00000000`76cae6ea USER32!ZwUserGetMessage+0xa
00000000`037cf7a0 000007fe`f7ea0d3a USER32!GetMessageW+0×34
00000000`037cf7d0 00000000`76d9cdcd WSDMon!Ncd::TPower::WindowMessageThread+0xe6
00000000`037cf870 00000000`76eec6e1 kernel32!BaseThreadInitThunk+0xd
00000000`037cf8a0 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

  13  Id: ecc.b34 Suspend: 1 Teb: 7ef85000 Unfrozen
ChildEBP RetAddr
0621fc18 75b86458 USER32!NtUserGetMessage+0x15
0621fc3c 74aa1404 USER32!GetMessageA+0xa2
0621fc74 76ea19f1 WINMM!mciwindow+0×102
0621fc80 7797d109 kernel32!BaseThreadInitThunk+0xe
0621fcc0 00000000 ntdll!_RtlUserThreadStart+0×23

Idle socket and network protocol threads:

   5  Id: ecc.920 Suspend: 1 Teb: 7efa3000 Unfrozen
ChildEBP RetAddr
0412f534 751b3b28 ntdll!ZwWaitForSingleObject+0x15
0412f574 751b2690 mswsock!SockWaitForSingleObject+0x19f
0412f660 771d3781 mswsock!WSPSelect+0x38c
0412f6dc 760f60fd ws2_32!select+0x456
0412fa34 760f2a78 WININET!ICAsyncThread::SelectThread+0x242
0412fa3c 76ea19f1 WININET!ICAsyncThread::SelectThreadWrapper+0xd
0412fa48 7797d109 kernel32!BaseThreadInitThunk+0xe
0412fa88 00000000 ntdll!_RtlUserThreadStart+0x23

   6  Id: ecc.b1c Suspend: 1 Teb: 7ef9d000 Unfrozen
ChildEBP RetAddr
047afa6c 751b1b25 ntdll!NtRemoveIoCompletion+0x15
047afaa4 76ea19f1 mswsock!SockAsyncThread+0x69
047afab0 7797d109 kernel32!BaseThreadInitThunk+0xe
047afaf0 00000000 ntdll!_RtlUserThreadStart+0x23

   7 Id: 820.f90 Suspend: 1 Teb: 7ffd9000 Unfrozen
ChildEBP RetAddr
018dff84 7c93e9ab ntdll!KiFastSystemCallRet (FPO: [0,0,0])
018dff88 60620e6c ntdll!ZwWaitForMultipleObjects+0xc
018dffb4 7c80b683 NETAPI32!NetbiosWaiter+0x73
018dffec 00000000 kernel32!BaseThreadStart+0x37

Function names showing passive nature of threads: 

   8  Id: 65c.b40 Suspend: 1 Teb: 000007ff`fffa6000 Unfrozen
Child-SP          RetAddr           Call Site
00000000`0259fdc8 00000000`76d9d820 ntdll!NtWaitForSingleObject+0xa
00000000`0259fdd0 000007fe`f8258084 kernel32!WaitForSingleObjectEx+0x9c
00000000`0259fe90 000007fe`fee994e7 wsnmp32!thrNotify+0×9c
00000000`0259fef0 000007fe`fee9967d msvcrt!endthreadex+0×47
00000000`0259ff20 00000000`76d9cdcd msvcrt!endthreadex+0×100
00000000`0259ff50 00000000`76eec6e1 kernel32!BaseThreadInitThunk+0xd
00000000`0259ff80 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

  12  Id: 65c.908 Suspend: 1 Teb: 000007ff`fff9e000 Unfrozen
Child-SP          RetAddr           Call Site
00000000`0368fd48 00000000`76d9d820 ntdll!NtWaitForSingleObject+0xa
00000000`0368fd50 000007fe`fa49afd0 kernel32!WaitForSingleObjectEx+0x9c
00000000`0368fe10 00000000`76d9cdcd FunDisc!CNotificationQueue::ThreadProc+0×2ec
00000000`0368fe70 00000000`76eec6e1 kernel32!BaseThreadInitThunk+0xd
00000000`0368fea0 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

  13  Id: 65c.904 Suspend: 1 Teb: 000007ff`fff9c000 Unfrozen
Child-SP          RetAddr           Call Site
00000000`034af9f8 00000000`76d9ed73 ntdll!NtWaitForMultipleObjects+0xa
00000000`034afa00 00000000`76cae96d kernel32!WaitForMultipleObjectsEx+0x10b
00000000`034afb10 00000000`76cae85e USER32!RealMsgWaitForMultipleObjectsEx+0x129
00000000`034afbb0 00000000`76ca3680 USER32!MsgWaitForMultipleObjectsEx+0x46
00000000`034afbf0 000007fe`fa49b60a USER32!MsgWaitForMultipleObjects+0x20
00000000`034afc30 00000000`76d9cdcd FunDisc!ListenerThread+0×1a6
00000000`034afd20 00000000`76eec6e1 kernel32!BaseThreadInitThunk+0xd
00000000`034afd50 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

  64  Id: 8f8.1050 Suspend: 1 Teb: 7ff74000 Unfrozen
ChildEBP RetAddr
0ef5fa48 7c82787b ntdll!KiFastSystemCallRet
0ef5fa4c 77c80a6e ntdll!NtRequestWaitReplyPort+0xc
0ef5fa98 77c7fcf0 rpcrt4!LRPC_CCALL::SendReceive+0x230
0ef5faa4 77c80673 rpcrt4!I_RpcSendReceive+0x24
0ef5fab8 77ce315a rpcrt4!NdrSendReceive+0x2b
0ef5fea0 771f4fbd rpcrt4!NdrClientCall2+0x22e
0ef5feb8 771f4f60 winsta!RpcWinStationWaitSystemEvent+0x1c
0ef5ff00 76f01422 winsta!WinStationWaitSystemEvent+0x51
0ef5ff24 0c922ace wtsapi32!WTSWaitSystemEvent+0×97
0ef5ff48 67823331 component!MonitorEvents+0xaf
0ef5ffb8 77e64829 msvcrt!_endthreadex+0xa3
0ef5ffec 00000000 kernel32!BaseThreadStart+0×34

   11 Id: 140c.e8c Suspend: 1 Teb: 7ffaf000 Unfrozen
ChildEBP RetAddr
01e3fec0 7c822114 ntdll!KiFastSystemCallRet
01e3fec4 77e6711b ntdll!NtWaitForMultipleObjects+0xc
01e3ff6c 77e61075 kernel32!WaitForMultipleObjectsEx+0x11a
01e3ff88 76928415 kernel32!WaitForMultipleObjects+0x18
01e3ffb8 77e66063 userenv!!NotificationThread+0×5f
01e3ffec 00000000 kernel32!BaseThreadStart+0×34

When in doubt it is always a good idea to examine threads in non-hanging processes to see their normal idle stack traces.

I’ll discuss passive threads from kernel space in the next part.

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 30)

Monday, October 15th, 2007

When a system is unresponsive or sluggish we usually check _ERESOURCE locks in kernel or complete memory dumps to see deadlock or high resource contention. However there is some chance that reported locks are purely accidental and appear in a crash dump because they just happened at that time. We need to look at Contention Count, Ticks and KernelTime in both blocking and blocked threads to recognize an Accidental Lock. Also the current version of WinDbg doesn’t distinguish between prolonged and accidental locks when we use !analyze -v -hang command and merely reports some lock chain it finds among equal alternatives.

Here is an example. The system was reported hang and kernel memory dump was saved. WinDbg analysis command reports one thread blocking 3 other threads and the driver on top of the blocking thread stack is AVDriver.sys. The algorithm WinDbg uses to point to specific image name is described here and in our case it chooses AVDriver:  

BLOCKED_THREAD:  8089d8c0

BLOCKING_THREAD:  8aab4700

LOCK_ADDRESS:  8859a570 -- (!locks 8859a570)

Resource @ 0x8859a570    Exclusively owned
    Contention Count = 3
    NumberOfExclusiveWaiters = 3
     Threads: 8aab4700-01<*>
     Threads Waiting On Exclusive Access:
              885d0020       88a7c020       8aafc7d8

1 total locks, 1 locks currently held

BUGCHECK_STR:  LOCK_HELD

FAULTING_THREAD:  8aab4700

STACK_TEXT:
f592f698 80832f7a nt!KiSwapContext+0x26
f592f6c4 80828705 nt!KiSwapThread+0x284
f592f70c f720a394 nt!KeDelayExecutionThread+0x2ab
WARNING: Stack unwind information not available. Following frames may be wrong.
f592f734 f720ae35 AVDriver+0×1394
f592f750 f720b208 AVDriver+0×1e35
f592f794 f721945a AVDriver+0×2208
f592f7cc 8081dcdf AVDriver+0×1045a
f592f7e0 f5b9f76a nt!IofCallDriver+0×45
f592f7f0 f5b9c621 Driver!FS_Dispatch+0xa4
f592f7fc 8081dcdf Driver!Kernel_dispatch+0×53
f592f810 f5eb2856 nt!IofCallDriver+0×45
f592f874 8081dcdf AVFilter!QueryFullName+0×5c10
f592f888 f5e9eae3 nt!IofCallDriver+0×45
f592f8b8 f5e9eca4 DrvFilter!PassThrough+0×115
f592f8d4 8081dcdf DrvFilter!Create+0xda
f592f8e8 808f8275 nt!IofCallDriver+0×45
f592f9d0 808f86bc nt!IopParseDevice+0xa35
f592fa08 80936689 nt!IopParseFile+0×46
f592fa88 80932e04 nt!ObpLookupObjectName+0×11f
f592fadc 808ea231 nt!ObOpenObjectByName+0xea
f592fb58 808eb4cb nt!IopCreateFile+0×447
f592fbb4 f57c8efd nt!IoCreateFile+0xa3
f592fc24 f57c9f29 srv!SrvIoCreateFile+0×36d
f592fcf0 f57ca5e4 srv!SrvNtCreateFile+0×5cc
f592fd78 f57adbc6 srv!SrvSmbNtCreateAndX+0×15c
f592fd84 f57c3451 srv!SrvProcessSmb+0xb7
f592fdac 80948bd0 srv!WorkerThread+0×138
f592fddc 8088d4e2 nt!PspSystemThreadStartup+0×2e
00000000 00000000 nt!KiThreadStartup+0×16

STACK_COMMAND:  .thread 0xffffffff8aab4700 ; kb

FOLLOWUP_IP:
AVDriver+1394
f720a394 eb85            jmp     AVDriver+0x131b (f720a31b)

MODULE_NAME: AVDriver

IMAGE_NAME:  AVDriver.sys

Motivated by this “discovery” we want to see all locks:

0: kd> !locks
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks...

Resource @ 0x895a62d8    Shared 1 owning threads
     Threads: 89570520-01<*>

Resource @ 0x897ceba8    Shared 1 owning threads
     Threads: 89584020-01<*>

Resource @ 0x8958e020    Shared 1 owning threads
     Threads: 89555020-01<*>

Resource @ 0x89590608    Shared 1 owning threads
     Threads: 89666020-01<*>

Resource @ 0x89efc398    Shared 1 owning threads
     Threads: 89e277c0-01<*>

Resource @ 0x88d70820    Shared 1 owning threads
     Threads: 88e43948-01<*>

Resource @ 0x89f2fb00    Shared 1 owning threads
     Threads: 89674688-01<*>

Resource @ 0x89c80370    Shared 1 owning threads
     Threads: 888496b8-01<*>

Resource @ 0x89bfdf08    Shared 1 owning threads
     Threads: 88b62910-01<*>

Resource @ 0x888b5488    Shared 1 owning threads
     Threads: 88536730-01<*>

Resource @ 0x89f2e348    Shared 1 owning threads
     Threads: 89295930-01<*>

Resource @ 0x891a0838    Shared 1 owning threads
     Threads: 88949020-01<*>

Resource @ 0x8825bf08    Shared 1 owning threads
     Threads: 882b9a08-01<*>

Resource @ 0x881a6510    Shared 1 owning threads
     Threads: 88a88338-01<*>

Resource @ 0x885c5890    Shared 1 owning threads
     Threads: 881ab020-01<*>

Resource @ 0x886633a8    Shared 1 owning threads
     Threads: 89b5f8b0-01<*>

Resource @ 0x88216390    Shared 1 owning threads
     Threads: 88820020-01<*>

Resource @ 0x88524490    Shared 1 owning threads
     Threads: 88073020-01<*>

Resource @ 0x88f6a020    Shared 1 owning threads
     Threads: 88e547b0-01<*>

Resource @ 0x88cf2020    Shared 1 owning threads
     Threads: 89af32d8-01<*>

Resource @ 0x889cea80    Shared 1 owning threads
     Threads: 88d18b40-01<*>

Resource @ 0x88486298    Shared 1 owning threads
     Threads: 88af7db0-01<*>

Resource @ 0x88b22270    Exclusively owned
    Contention Count = 4
    NumberOfExclusiveWaiters = 4
     Threads: 8aad07d8-01<*>
     Threads Waiting On Exclusive Access:
              8ad78020       887abdb0       88eb39a8       8aa1f668

Resource @ 0x88748c20    Exclusively owned
    Contention Count = 2
    NumberOfExclusiveWaiters = 2
     Threads: 8873c8d8-01<*>
     Threads Waiting On Exclusive Access:
              88477478       88db6020

Resource @ 0x8859a570    Exclusively owned
    Contention Count = 3
    NumberOfExclusiveWaiters = 3
     Threads: 8aab4700-01<*>
     Threads Waiting On Exclusive Access:
              885d0020       88a7c020       8aafc7d8

KD: Scanning for held locks...
18911 total locks, 25 locks currently held

We can ignore shared locks and concentrate on the last 3 exclusively owned resources. It looks suspicious that Contention Count has the same number as the number of threads waiting on exclusive access (NumberOfExclusiveWaiters). This means that these resources had never been used before. If we dump locks verbosely we would see that blocked threads had been waiting no more than 2 seconds, for example, for resource 0×8859a570:

0: kd> !thread 885d0020; !thread 88a7c020; !thread 8aafc7d8
THREAD 885d0020  Cid 0004.1c34  Teb: 00000000 Win32Thread: 00000000 WAIT: (Unknown) KernelMode Non-Alertable
    89908d50  SynchronizationEvent
    885d0098  NotificationTimer
Not impersonating
DeviceMap                 e10022c8
Owning Process            8ad80648 Image:         System
Wait Start TickCount      7689055  Ticks: 127 (0:00:00:01.984)
Context Switch Count      248
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Start Address srv!WorkerThread (0xf57c3394)
Stack Init b4136000 Current b4135b74 Base b4136000 Limit b4133000 Call 0
Priority 9 BasePriority 9 PriorityDecrement 0
ChildEBP RetAddr
b4135b8c 80832f7a nt!KiSwapContext+0×26
b4135bb8 8082925c nt!KiSwapThread+0×284
b4135c00 8087c1ad nt!KeWaitForSingleObject+0×346
b4135c3c 8087c3a1 nt!ExpWaitForResource+0xd5
b4135c5c f57c9e95 nt!ExAcquireResourceExclusiveLite+0×8d
b4135cf0 f57ca5e4 srv!SrvNtCreateFile+0×510
b4135d78 f57adbc6 srv!SrvSmbNtCreateAndX+0×15c
b4135d84 f57c3451 srv!SrvProcessSmb+0xb7
b4135dac 80948bd0 srv!WorkerThread+0×138
b4135ddc 8088d4e2 nt!PspSystemThreadStartup+0×2e
00000000 00000000 nt!KiThreadStartup+0×16

THREAD 88a7c020  Cid 0004.3448  Teb: 00000000 Win32Thread: 00000000 WAIT: (Unknown) KernelMode Non-Alertable
    89908d50  SynchronizationEvent
    88a7c098  NotificationTimer
Not impersonating
DeviceMap                 e10022c8
Owning Process            8ad80648  Image:         System
Wait Start TickCount      7689112   Ticks: 70 (0:00:00:01.093)
Context Switch Count      210
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Start Address srv!WorkerThread (0xf57c3394)
Stack Init b55dd000 Current b55dcb74 Base b55dd000 Limit b55da000 Call 0
Priority 9 BasePriority 9 PriorityDecrement 0
ChildEBP RetAddr
b55dcb8c 80832f7a nt!KiSwapContext+0×26
b55dcbb8 8082925c nt!KiSwapThread+0×284
b55dcc00 8087c1ad nt!KeWaitForSingleObject+0×346
b55dcc3c 8087c3a1 nt!ExpWaitForResource+0xd5
b55dcc5c f57c9e95 nt!ExAcquireResourceExclusiveLite+0×8d
b55dccf0 f57ca5e4 srv!SrvNtCreateFile+0×510
b55dcd78 f57adbc6 srv!SrvSmbNtCreateAndX+0×15c
b55dcd84 f57c3451 srv!SrvProcessSmb+0xb7
b55dcdac 80948bd0 srv!WorkerThread+0×138
b55dcddc 8088d4e2 nt!PspSystemThreadStartup+0×2e
00000000 00000000 nt!KiThreadStartup+0×16

THREAD 8aafc7d8  Cid 0004.058c  Teb: 00000000 Win32Thread: 00000000 WAIT: (Unknown) KernelMode Non-Alertable
    89908d50  SynchronizationEvent
    8aafc850  NotificationTimer
Not impersonating
DeviceMap                 e10022c8
Owning Process            8ad80648  Image:         System
Wait Start TickCount      7689171   Ticks: 11 (0:00:00:00.171)
Context Switch Count      310
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Start Address srv!WorkerThread (0xf57c3394)
Stack Init f592c000 Current f592bb18 Base f592c000 Limit f5929000 Call 0
Priority 9 BasePriority 9 PriorityDecrement 0
ChildEBP RetAddr
f592bb30 80832f7a nt!KiSwapContext+0×26
f592bb5c 8082925c nt!KiSwapThread+0×284
f592bba4 8087c1ad nt!KeWaitForSingleObject+0×346
f592bbe0 8087c3a1 nt!ExpWaitForResource+0xd5
f592bc00 f57c8267 nt!ExAcquireResourceExclusiveLite+0×8d
f592bc18 f57ff0ed srv!UnlinkRfcbFromLfcb+0×33
f592bc34 f57ff2ea srv!SrvCompleteRfcbClose+0×1df
f592bc54 f57b5e8f srv!CloseRfcbInternal+0xb6
f592bc78 f57ce8a9 srv!SrvCloseRfcbsOnSessionOrPid+0×74
f592bc94 f57e2b22 srv!SrvCloseSession+0xb0
f592bcb8 f57aeb12 srv!SrvCloseSessionsOnConnection+0xa9
f592bcd4 f57c79ed srv!SrvCloseConnection+0×143
f592bd04 f5808c50 srv!SrvCloseConnectionsFromClient+0×17f
f592bdac 80948bd0 srv!WorkerThread+0×138
f592bddc 8088d4e2 nt!PspSystemThreadStartup+0×2e
00000000 00000000 nt!KiThreadStartup+0×16

Blocking threads themselves are not blocked and active: the number of ticks passed since their last wait or preemption is 0. This could be a sign of CPU spike pattern. However their accumulated KernelTime is less than a second:

0: kd> !thread 8aad07d8
THREAD 8aad07d8  Cid 0004.0580  Teb: 00000000 Win32Thread: 00000000 WAIT: (Unknown) KernelMode Non-Alertable
    8aad0850  NotificationTimer
IRP List:
    8927ade0: (0006,0220) Flags: 00000884  Mdl: 00000000
Impersonation token:  eafdc030 (Level Impersonation)
DeviceMap                 e5d69340
Owning Process            8ad80648       Image:         System
Wait Start TickCount      7689182        Ticks: 0
Context Switch Count      915582
UserTime                  00:00:00.000
KernelTime                00:00:00.125
Start Address srv!WorkerThread (0xf57c3394)
Stack Init f59d8000 Current f59d7680 Base f59d8000 Limit f59d5000 Call 0
Priority 9 BasePriority 9 PriorityDecrement 0

0: kd> !thread 8873c8d8
THREAD 8873c8d8  Cid 0004.2898  Teb: 00000000 Win32Thread: 00000000 WAIT: (Unknown) KernelMode Non-Alertable
    8873c950  NotificationTimer
IRP List:
    882a8de0: (0006,0220) Flags: 00000884  Mdl: 00000000
Impersonation token:  eafdc030 (Level Impersonation)
DeviceMap                 e5d69340
Owning Process            8ad80648       Image:         System
Wait Start TickCount      7689182        Ticks: 0
Context Switch Count      917832
UserTime                  00:00:00.000
KernelTime                00:00:00.031
Start Address srv!WorkerThread (0xf57c3394)
Stack Init ac320000 Current ac31f680 Base ac320000 Limit ac31d000 Call 0
Priority 9 BasePriority 9 PriorityDecrement 0

0: kd> !thread 8aab4700
THREAD 8aab4700  Cid 0004.0588  Teb: 00000000 Win32Thread: 00000000 WAIT: (Unknown) KernelMode Non-Alertable
    8aab4778  NotificationTimer
IRP List:
    88453008: (0006,0220) Flags: 00000884  Mdl: 00000000
Impersonation token:  e9a82728 (Level Impersonation)
DeviceMap                 eb45f108
Owning Process            8ad80648       Image:         System
Wait Start TickCount      7689182        Ticks: 0
Context Switch Count      1028220
UserTime                  00:00:00.000
KernelTime                00:00:00.765
Start Address srv!WorkerThread (0xf57c3394)
Stack Init f5930000 Current f592f680 Base f5930000 Limit f592d000 Call 0
Priority 9 BasePriority 9 PriorityDecrement 0

Based on this observation we could say that locks were accidental and indeed, when the problem happened again, the new dump didn’t show them.

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 29)

Monday, October 8th, 2007

Some Windows synchronization objects like executive resources and critical sections have a struct member called ContentionCount. This is the number of times a resource was accessed or, in another words, it is the accumulated number of threads waiting for an object: when a thread tries to acquire an object and put into a wait state the count is incremented. Hence the name of this pattern: High Contention.

Here is an example. In a kernel memory dump we have just one exclusively owned lock and seems no other threads were blocked by it at the time the dump was saved. However the high contention count reveals CPU spike:

3: kd> !locks
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks...

Resource @ 0x8abc11f0    Exclusively owned
    Contention Count = 19648535
     Threads: 896395f8-01<*>
KD: Scanning for held locks…

Resource @ 0x896fab88    Shared 1 owning threads
     Threads: 88c78608-01<*>
KD: Scanning for held locks...
15464 total locks, 2 locks currently held

3: kd> !thread 896395f8
THREAD 896395f8  Cid 04c0.0138  Teb: 7ffde000 Win32Thread: bc922d20 RUNNING on processor 1
Not impersonating
DeviceMap                 e3d4c008
Owning Process            8a035020       Image:         MyApp.exe
Wait Start TickCount      36969283       Ticks: 0
Context Switch Count      1926423                 LargeStack
UserTime                  00:00:53.843
KernelTime                00:13:10.703
Win32 Start Address 0×00401478
Start Address 0×77e617f8
Stack Init ba14b000 Current ba14abf8 Base ba14b000 Limit ba146000 Call 0
Priority 11 BasePriority 6 PriorityDecrement 5
ChildEBP RetAddr  Args to Child
ba14ac94 bf8c6505 001544c8 bf995948 000c000a nt!_wcsicmp+0×3a (FPO: [Non-Fpo])
ba14ace0 bf8c6682 00000000 00000000 00000000 win32k!_FindWindowEx+0xfb (FPO: [Non-Fpo])
ba14ad48 8088978c 00000000 00000000 0012f8d4 win32k!NtUserFindWindowEx+0xef (FPO: [Non-Fpo])
ba14ad48 7c8285ec 00000000 00000000 0012f8d4 nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ ba14ad64)

3: kd> !process 8a035020
PROCESS 8a035020  SessionId: 9  Cid: 04c0    Peb: 7ffdf000  ParentCid: 10e8
    DirBase: cffaf7a0  ObjectTable: e4ba30a0  HandleCount:  73.
    Image: MyApp.exe
    VadRoot 88bc1bf8 Vads 82 Clone 0 Private 264. Modified 0. Locked 0.
    DeviceMap e3d4c008
    Token                             e5272028
    ElapsedTime                       00:14:19.360
    UserTime                          00:00:53.843
    KernelTime                        00:13:10.703
    QuotaPoolUsage[PagedPool]         40660
    QuotaPoolUsage[NonPagedPool]      3280
    Working Set Sizes (now,min,max)  (1139, 50, 345) (4556KB, 200KB, 1380KB)
    PeakWorkingSetSize                1141
    VirtualSize                       25 Mb
    PeakVirtualSize                   27 Mb
    PageFaultCount                    1186
    MemoryPriority                    BACKGROUND
    BasePriority                      6
    CommitCharge                      315

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 28)

Wednesday, September 26th, 2007

Sometimes we have a problem that some functionality is not available or it is unresponsive when we request it. We can suppose that the process implementing that functionality has crashed or hangs. If we know the relationship between processes we can request several user dumps at once or a complete memory dump to analyze the dependency between processes by looking at their stack traces. This is an example of the system level crash dump analysis pattern that I call Coupled Processes.

Process relationship can be implemented via different interprocess communication mechanisms (IPC), for example, Remote Procedure Call (RPC) via LPC (Local Procedure Call) which can be easily identified in stack traces.

My favorite example here is when some application tries to print and hangs. Printing API is exported from WINSPOOL.DLL and it forwards via RPC most requests to Windows Print Spooler service. Therefore it is logical to take two dumps, one from that application and one from spoolsv.exe. Similar example is from Citrix Presentation Server environments related to printer autocreation when there are dependencies between Citrix Printing Service CpSvc.exe and spoolsv.exe. Therefore if new user connections hang and restarting both printing services resolves the issue then we might need to analyze dumps from both services together to confirm this Procedure Call Chain and find the problem 3rd-party printing component or driver.

Back to my favorite example. In the hang application we have the following thread:

  18  Id: 2130.6320 Suspend: 1 Teb: 7ffa8000 Unfrozen
ChildEBP RetAddr
01eae170 7c821c94 ntdll!KiFastSystemCallRet
01eae174 77c72700 ntdll!NtRequestWaitReplyPort+0xc
01eae1c8 77c713ba rpcrt4!LRPC_CCALL::SendReceive+0x230
01eae1d4 77c72c7f rpcrt4!I_RpcSendReceive+0x24
01eae1e8 77ce219b rpcrt4!NdrSendReceive+0x2b
01eae5d0 7307c9ef rpcrt4!NdrClientCall2+0x22e
01eae5e8 73082d8d winspool!RpcAddPrinter+0x1c
01eaea70 0040d81a winspool!AddPrinterW+0x102
01eaef58 0040ee7c App!AddNewPrinter+0x816
...
...
...

Notice winspool and rpcrt4 modules. The application is calling spooler service using RPC to add a new printer and waiting for a reply back. Looking at spooler service dump shows several threads displaying message boxes and waiting for user input: 

  20  Id: 790.5950 Suspend: 1 Teb: 7ffa2000 Unfrozen
ChildEBP RetAddr  Args to Child
03deea70 7739d02f 77392bf3 00000000 00000000 ntdll!KiFastSystemCallRet
03deeaa8 7738f122 03dd0058 00000000 00000001 user32!NtUserWaitMessage+0xc
03deead0 773a1722 77380000 00123690 00000000 user32!InternalDialogBox+0xd0
03deed90 773a1004 03deeeec 03dae378 03dae160 user32!SoftModalMessageBox+0x94b
03deeee0 773b1a28 03deeeec 00000028 00000000 user32!MessageBoxWorker+0x2ba
03deef38 773b19c4 00000000 03defb9c 03def39c user32!MessageBoxTimeoutW+0x7a
03deef58 773b19a0 00000000 03defb9c 03def39c user32!MessageBoxExW+0x1b
03deef74 021f265b 00000000 03defb9c 03def39c user32!MessageBoxW+0×45
WARNING: Stack unwind information not available. Following frames may be wrong.
03deef88 00000000 03dae160 03deffec 03dae16a PrinterDriver!UninstallerInstall+0×2cb

Dumping the 3rd parameter of MessageBoxW using WinDbg du command shows the message:

“Installation of the software for your printer is now complete. Restart your computer to make the new settings active.”

Another example when one process starts another and is waiting for it to finish:

0 Id: 2a34.24d0 Suspend: 1 Teb: 7ffde000 Unfrozen
ChildEBP RetAddr
0007ec8c 7c822124 ntdll!KiFastSystemCallRet
0007ec90 77e6bad8 ntdll!NtWaitForSingleObject+0xc
0007ed00 77e6ba42 kernel32!WaitForSingleObjectEx+0xac
0007ed14 01002f4c kernel32!WaitForSingleObject+0x12
0007f79c 01003137 userinit!ExecApplication+0x2d3
0007f7dc 0100366b userinit!ExecProcesses+0x1bb
0007fe68 010041fd userinit!StartTheShell+0x132
0007ff1c 010056f1 userinit!WinMain+0x263
0007ffc0 77e523e5 userinit!WinMainCRTStartup+0x186
0007fff0 00000000 kernel32!BaseProcessStart+0x23

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 27)

Friday, September 14th, 2007

Sometimes a problem can be identified not from a single Stack Trace pattern but from a Stack Trace Collection

These include Coupled ProcessesProcedure Call Chains and Blocked Threads. All of them will be discussed in subsequent parts and in this part I only discuss various methods to list stack traces.

  • Process dumps including various process minidumps:

~*kv command lists all process threads

!findstack module[!symbol] 2 command filters all stack traces to show ones containing module or module!symbol

!uniqstack command

  • Kernel minidumps:

have only one problem thread. kv command or its variant is suffice.

  • Kernel and complete memory dumps:

!process 0 ff command lists all processes and their threads including user space process thread stacks for complete memory dumps. This command is valid for Windows XP and later. For older systems use WinDbg scripts

!stacks 2 [module[!symbol]] command shows kernel mode stack traces and you can filter the output based on module or module!symbol. Filtering is valid only for dumps from Windows XP and later systems    

~[ProcessorN]s;.reload /user;kv command sequence shows stack trace for the running thread on the specified processor.

!sprocess 0n<SessionId> ff lists all processes and their threads for the specified [terminal services] session. 

!for_each_thread “.thread /r /p @#Thread; kvallows execution of stack trace command variants per each thread. The following script takes the advantage of this command to list complete stack traces from an x64 system.

The processor change command is illustrated in this example:

0: kd> ~2s

2: kd> k
ChildEBP RetAddr
eb42bd58 00000000 nt!KiIdleLoop+0x14

2: kd> ~1s;.reload /user;k
Loading User Symbols
...
ChildEBP RetAddr
be4f8c30 eb091f43 i8042prt!I8xProcessCrashDump+0x53
be4f8c8c 8046bfe2 i8042prt!I8042KeyboardInterruptService+0x15d
be4f8c8c 8049470f nt!KiInterruptDispatch+0x32
be4f8d54 80468389 nt!NtSetEvent+0x71
be4f8d54 77f8290a nt!KiSystemService+0xc9
081cfefc 77f88266 ntdll!ZwSetEvent+0xb
081cff0c 77f881b1 ntdll!RtlpUnWaitCriticalSection+0x1b
081cff14 1b00c7d1 ntdll!RtlLeaveCriticalSection+0x1d
081cff4c 1b0034da msjet40!Database::ReadPages+0x81
081cffb4 7c57b3bc msjet40!System::WorkerThread+0x115
081cffec 00000000 KERNEL32!BaseThreadStart+0x52

Example of !findstack command (process dump):

0:000> !findstack kernel32!RaiseException 2
Thread 000, 1 frame(s) match
* 00 0013b3f8 72e8d3ef kernel32!RaiseException+0x53
  01 0013b418 72e9a26b msxml3!Exception::raiseException+0x5f
  02 0013b424 72e8ff00 msxml3!Exception::_throwError+0x22
  03 0013b46c 72e6abaa msxml3!COMSafeControlRoot::getBaseURL+0x3d
  04 0013b4bc 72e6a888 msxml3!Document::loadXML+0x82
  05 0013b510 64b73a9b msxml3!DOMDocumentWrapper::loadXML+0x5a
  06 0013b538 64b74eb6 iepeers!CPersistUserData::initXMLCache+0xa6
  07 0013b560 77d0516e iepeers!CPersistUserData::load+0xfc
  08 0013b57c 77d14abf oleaut32!DispCallFunc+0x16a
...
...
...
  66 0013fec8 0040243d shdocvw!IEWinMain+0x129
  67 0013ff1c 00402744 iexplore!WinMain+0x316
  68 0013ffc0 77e6f23b iexplore!WinMainCRTStartup+0x182
  69 0013fff0 00000000 kernel32!BaseProcessStart+0x23

Example of !stacks command (kernel dump):

2: kd> !stacks 2 nt!PspExitThread
Proc.Thread  .Thread  Ticks   ThreadState Blocker
                            [8a390818 System]

                            [8a1bbbf8 smss.exe]

                            [8a16cbf8 csrss.exe]

                            [89c14bf0 winlogon.exe]

                            [89dda630 services.exe]

                            [89c23af0 lsass.exe]

                            [8a227470 svchost.exe]

                            [89f03bb8 svchost.exe]

                            [89de3820 svchost.exe]

                            [89d09b60 svchost.exe]

                            [89c03530 ccEvtMgr.exe]

                            [89b8f4f0 ccSetMgr.exe]

                            [89dfe8c0 SPBBCSvc.exe]

                            [89c9db18 svchost.exe]

                            [89dfa268 spoolsv.exe]

                            [89dfa6b8 msdtc.exe]

                            [89df38f0 CpSvc.exe]

                            [89d97d88 DefWatch.exe]

                            [89e04020 IBMSPSVC.EXE]

                            [89b54710 IBMSPREM.EXE]

                            [89d9e4b0 IBMSPREM.EXE]

                            [89c2c4e8 svchost.exe]

                            [89d307c0 SavRoam.exe]

                            [89bfcd88 Rtvscan.exe]

                            [89b53b60 uphclean.exe]

                            [89c24020 AgentSVC.exe]

                            [89d75b60 sAginst.exe]

                            [89cf0d88 CdfSvc.exe]

                            [89d87020 cdmsvc.exe]

                            [89dafd88 ctxxmlss.exe]

                            [89d8dd88 encsvc.exe]

                            [89d06d88 ImaSrv.exe]

                            [89d37b60 mfcom.exe]

                            [89c8bb18 SmaService.exe]

                            [89d2ba80 svchost.exe]

                            [89ce8630 XTE.exe]

                            [89b64b60 XTE.exe]

                            [89b7c680 ctxcpusched.exe]

                            [88d94a88 ctxcpuusync.exe]

                            [89ba5418 unsecapp.exe]

                            [89d846e0 wmiprvse.exe]

                            [89cda9d8 ctxwmisvc.exe]

                            [88d6cb78 logon.scr]

                            [88ba0a70 csrss.exe]

                            [88961968 winlogon.exe]

                            [8865f740 rdpclip.exe]

                            [8858db20 wfshell.exe]

                            [88754020 explorer.exe]

                            [88846d88 BacsTray.exe]

                            [886b6180 ccApp.exe]

                            [884bc020 fppdis3a.exe]

                            [885cb350 ctfmon.exe]

                            [888bb918 cscript.exe]

                            [8880b3c8 cscript.exe]

                            [88ad2950 csrss.exe]
 b68.00215c  88930020 0000000 RUNNING    nt!KeBugCheckEx+0x1b
                                        nt!MiCheckSessionPoolAllocations+0xe3
                                        nt!MiDereferenceSessionFinal+0x183
                                        nt!MmCleanProcessAddressSpace+0x6b
                                        nt!PspExitThread+0x5f1
                                        nt!PspTerminateThreadByPointer+0x4b
                                        nt!PspSystemThreadStartup+0x3c
                                        nt!KiThreadStartup+0x16

                            [88629310 winlogon.exe]

                            [88a4d9b0 csrss.exe]

                            [88d9f8b0 winlogon.exe]

                            [88cd5840 wfshell.exe]

                            [8a252440 OUTLOOK.EXE]

                            [8a194bf8 WINWORD.EXE]

                            [88aabd20 ctfmon.exe]

                            [889ef440 EXCEL.EXE]

                            [88bec838 HogiaGUI2.exe]

                            [88692020 csrss.exe]

                            [884dd508 winlogon.exe]

                            [88be1d88 wfshell.exe]

                            [886a7d88 OUTLOOK.EXE]

                            [889baa70 WINWORD.EXE]

                            [8861e3d0 ctfmon.exe]

                            [887bbb68 EXCEL.EXE]

                            [884e4020 csrss.exe]

                            [8889d218 winlogon.exe]

                            [887c8020 wfshell.exe]

Threads Processed: 1101

What if we have a list of processes from a complete memory dump by using !process 0 0 command and we want to interrogate the specific process? In this case we need to switch to that process and reload user space symbol files (.process /r /p address)

There is also a separate command to reload user space symbol files any time (.reload /user).

After switching we can list threads (!process address), dump or search process virtual memory, etc. For example:

1: kd> !process 0 0
**** NT ACTIVE PROCESS DUMP ****
PROCESS 890a3320  SessionId: 0  Cid: 0008    Peb: 00000000  ParentCid: 0000
    DirBase: 00030000  ObjectTable: 890a3e08  TableSize: 405.
    Image: System

PROCESS 889dfd60  SessionId: 0  Cid: 0144    Peb: 7ffdf000  ParentCid: 0008
    DirBase: 0b9e7000  ObjectTable: 889fdb48  TableSize: 212.
    Image: SMSS.EXE

PROCESS 890af020  SessionId: 0  Cid: 0160    Peb: 7ffdf000  ParentCid: 0144
    DirBase: 0ce36000  ObjectTable: 8898e308  TableSize: 747.
    Image: CSRSS.EXE

PROCESS 8893d020  SessionId: 0  Cid: 0178    Peb: 7ffdf000  ParentCid: 0144
    DirBase: 0d33b000  ObjectTable: 890ab4c8  TableSize: 364.
    Image: WINLOGON.EXE

PROCESS 88936020  SessionId: 0  Cid: 0194    Peb: 7ffdf000  ParentCid: 0178
    DirBase: 0d7d5000  ObjectTable: 88980528  TableSize: 872.
    Image: SERVICES.EXE

PROCESS 8897f020  SessionId: 0  Cid: 01a0    Peb: 7ffdf000  ParentCid: 0178
    DirBase: 0d89d000  ObjectTable: 889367c8  TableSize: 623.
    Image: LSASS.EXE

1: kd> .process /r /p 8893d020
Implicit process is now 8893d020
Loading User Symbols
...

1: kd> !process 8893d020
PROCESS 8893d020  SessionId: 0  Cid: 0178    Peb: 7ffdf000  ParentCid: 0144
    DirBase: 0d33b000  ObjectTable: 890ab4c8  TableSize: 364.
    Image: WINLOGON.EXE
    VadRoot 8893a508 Clone 0 Private 1320. Modified 45178. Locked 0.
    DeviceMap 89072448
    Token                             e392f8d0
    ElapsedTime                        9:54:06.0882
    UserTime                          0:00:00.0071
    KernelTime                        0:00:00.0382
    QuotaPoolUsage[PagedPool]         34828
    QuotaPoolUsage[NonPagedPool]      43440
    Working Set Sizes (now,min,max)  (737, 50, 345) (2948KB, 200KB, 1380KB)
    PeakWorkingSetSize                2764
    VirtualSize                       46 Mb
    PeakVirtualSize                   52 Mb
    PageFaultCount                    117462
    MemoryPriority                    FOREGROUND
    BasePriority                      13
    CommitCharge                      1861

        THREAD 8893dda0  Cid 178.15c  Teb: 7ffde000  Win32Thread: a2034908 WAIT: (WrUserRequest) UserMode Non-Alertable
            8893bee0  SynchronizationEvent
        Not impersonating
        Owning Process 8893d020
        Wait Start TickCount    29932455      Elapsed Ticks: 7
        Context Switch Count    28087                   LargeStack
        UserTime                  0:00:00.0023
        KernelTime                0:00:00.0084
        Start Address winlogon!WinMainCRTStartup (0x0101cbb0)
        Stack Init eb1b0000 Current eb1afcc8 Base eb1b0000 Limit eb1ac000 Call 0
        Priority 15 BasePriority 15 PriorityDecrement 0 DecrementCount 0

        ChildEBP RetAddr  Args to Child
        eb1afce0 8042d893 00000000 a2034908 00000001 nt!KiSwapThread+0x1b1
        eb1afd08 a00019c2 8893bee0 0000000d 00000001 nt!KeWaitForSingleObject+0x1a3
        eb1afd44 a0013993 000020ff 00000000 00000001 win32k!xxxSleepThread+0x18a
        eb1afd54 a001399f 0006fdd8 80468389 00000000 win32k!xxxWaitMessage+0xe
        eb1afd5c 80468389 00000000 00000000 00000000 win32k!NtUserWaitMessage+0xb
        eb1afd5c 77e58b53 00000000 00000000 00000000 nt!KiSystemService+0xc9
        0006fdd0 77e33630 00000000 00000000 0000ffff USER32!NtUserWaitMessage+0xb
        0006fe04 77e44327 000100d2 00000000 00000010 USER32!DialogBox2+0x216
        0006fe28 77e38d37 76b90000 76c75c78 00000000 USER32!InternalDialogBox+0xd1
        0006fe48 77e39eba 76b90000 76c75c78 00000000 USER32!DialogBoxIndirectParamAorW+0x34
        0006fe6c 01011749 76b90000 00000578 00000000 USER32!DialogBoxParamW+0x3d
        0006fea8 01018bd3 000755e8 76b90000 00000578 winlogon!TimeoutDialogBoxParam+0x27
        0006fee0 76b93701 000755e8 76b90000 00000578 winlogon!WlxDialogBoxParam+0×7b
        0006ff08 010164c6 0008d0e0 5ffa0000 000755e8 3rdPartyGINA!WlxDisplaySASNotice+0×43
        0006ff20 01014960 000755e8 00000005 00072c9c winlogon!MainLoop+0×96
        0006ff58 0101cd06 00071fc8 00000000 00072c9c winlogon!WinMain+0×37a
        0006fff4 00000000 7ffdf000 000000c8 00000100 winlogon!WinMainCRTStartup+0×156

        THREAD 88980020  Cid 178.188  Teb: 7ffdc000  Win32Thread: 00000000 WAIT: (DelayExecution) UserMode Alertable
            88980108  NotificationTimer
        Not impersonating
        Owning Process 8893d020
        Wait Start TickCount    29930810      Elapsed Ticks: 1652
        Context Switch Count    15638
        UserTime                  0:00:00.0000
        KernelTime                0:00:00.0000
        Start Address KERNEL32!BaseThreadStartThunk (0x7c57b740)
        Win32 Start Address ntdll!RtlpTimerThread (0x77faa02d)
        Stack Init bf6f7000 Current bf6f6cc4 Base bf6f7000 Limit bf6f4000 Call 0
        Priority 13 BasePriority 13 PriorityDecrement 0 DecrementCount 0

        ChildEBP RetAddr  Args to Child
        bf6f6cdc 8042d340 bf6f6d64 00bfffac 00bfffac nt!KiSwapThread+0x1b1
        bf6f6d04 8052aac9 8046c101 00000001 bf6f6d34 nt!KeDelayExecutionThread+0x182
        bf6f6d54 80468389 00000001 00bfffac 00000000 nt!NtDelayExecution+0x7f
        bf6f6d54 77f82831 00000001 00bfffac 00000000 nt!KiSystemService+0xc9
        00bfff9c 77f842c4 00000001 00bfffac 00000000 ntdll!NtDelayExecution+0xb
        00bfffb4 7c57b3bc 0006fe60 00000000 00000000 ntdll!RtlpTimerThread+0x42
        00bfffec 00000000 77faa02d 0006fe60 00000000 KERNEL32!BaseThreadStart+0x52

1: kd> dds 0006fee0
0006fee0  0006ff08
0006fee4  76b93701 3rdPartyGINA!WlxDisplaySASNotice+0x43
0006fee8  000755e8
0006feec  76b90000 3rdParty
0006fef0  00000578
0006fef4  00000000
0006fef8  76b9370b 3rdParty!WlxDisplaySASNotice+0x4d
0006fefc  0008d0e0
0006ff00  00000008
0006ff04  00000080
0006ff08  0006ff20
0006ff0c  010164c6 winlogon!MainLoop+0x96
0006ff10  0008d0e0
0006ff14  5ffa0000
0006ff18  000755e8
0006ff1c  00000000
0006ff20  0006ff58
0006ff24  01014960 winlogon!WinMain+0x37a
0006ff28  000755e8
0006ff2c  00000005
0006ff30  00072c9c
0006ff34  00000001
0006ff38  000001bc
0006ff3c  00000005
0006ff40  00000001
0006ff44  0000000d
0006ff48  00000000
0006ff4c  00000000
0006ff50  00000000
0006ff54  0000ffe4
0006ff58  0006fff4
0006ff5c  0101cd06 winlogon!WinMainCRTStartup+0x156

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 26)

Tuesday, September 11th, 2007

Sometimes we get a process dump from x64 Windows and when we load it into WinDbg we get the output telling us that an exception or a breakpoint comes from wow64.dll. For example:

Loading Dump File [X:\ppid2088.dmp]
User Mini Dump File with Full Memory: Only application data is available

Comment: 'Userdump generated complete user-mode minidump with Exception Monitor function on SERVER01'
Symbol search path is: srv*c:\mss*http://msdl.microsoft.com/download/symbols
Executable search path is:
Windows Server 2003 Version 3790 (Service Pack 2) MP (4 procs) Free x64
Product: Server, suite: TerminalServer
Debug session time: Tue Sep  4 13:36:14.000 2007 (GMT+2)
System Uptime: 6 days 3:32:26.081
Process Uptime: 0 days 0:01:54.000
WARNING: tsappcmp overlaps ws2_32
WARNING: msvcp60 overlaps oleacc
WARNING: tapi32 overlaps rasapi32
WARNING: rtutils overlaps rasman
WARNING: dnsapi overlaps rasapi32
WARNING: wldap32 overlaps dnsapi
WARNING: ntshrui overlaps userenv
WARNING: wtsapi32 overlaps dnsapi
WARNING: winsta overlaps setupapi
WARNING: activeds overlaps rtutils
WARNING: activeds overlaps rasman
WARNING: adsldpc overlaps activeds
WARNING: drprov overlaps apphelp
WARNING: netui1 overlaps netui0
WARNING: davclnt overlaps apphelp
...
This dump file has an exception of interest stored in it.
The stored exception information can be accessed via .ecxr.
(2088.2fe4): Unknown exception - code 000006d9 (first/second chance not available)
wow64!Wow64NotifyDebugger+0×9:
00000000`6b006369 b001            mov     al,1

Analysis shows that some run-time exception was raised but the stack trace shows only WOW64 CPU simulation code in all process threads:

0:000> !analyze -v
*********************************************************
*                                                       *
*                  Exception Analysis                   *
*                                                       *
*********************************************************

FAULTING_IP:
kernel32!RaiseException+53
00000000`7d4e2366 5e              pop     rsi

EXCEPTION_RECORD:  ffffffffffffffff -- (.exr 0xffffffffffffffff)
ExceptionAddress: 000000007d4e2366 (kernel32!RaiseException+0x0000000000000053)
   ExceptionCode: 000006d9
  ExceptionFlags: 00000001
NumberParameters: 0

DEFAULT_BUCKET_ID:  STACK_CORRUPTION

PROCESS_NAME:  App.exe

ERROR_CODE: (NTSTATUS) 0x6d9 - There are no more endpoints available from the endpoint mapper.

NTGLOBALFLAG:  0

APPLICATION_VERIFIER_FLAGS:  0

LAST_CONTROL_TRANSFER:  from 000000006b0064f2 to 000000006b006369

FOLLOWUP_IP:
wow64!Wow64NotifyDebugger+9
00000000`6b006369 b001            mov     al,1

SYMBOL_STACK_INDEX:  0

SYMBOL_NAME:  wow64!Wow64NotifyDebugger+9

FOLLOWUP_NAME:  MachineOwner

MODULE_NAME: wow64

IMAGE_NAME:  wow64.dll

DEBUG_FLR_IMAGE_TIMESTAMP:  45d6943d

FAULTING_THREAD:  0000000000002fe4

PRIMARY_PROBLEM_CLASS:  STACK_CORRUPTION

BUGCHECK_STR:  APPLICATION_FAULT_STACK_CORRUPTION

STACK_COMMAND:  ~0s; .ecxr ; dt ntdll!LdrpLastDllInitializer BaseDllName ; dt ntdll!LdrpFailureData ; kb

FAILURE_BUCKET_ID:  X64_APPLICATION_FAULT_STACK_CORRUPTION_wow64!Wow64NotifyDebugger+9

BUCKET_ID:  X64_APPLICATION_FAULT_STACK_CORRUPTION_wow64!Wow64NotifyDebugger+9

Followup: MachineOwner
---------

0:000> ~*k

.  0  Id: 2088.2fe4 Suspend: 1 Teb: 00000000`7efdb000 Unfrozen
Child-SP          RetAddr           Call Site
00000000`0016e190 00000000`6b0064f2 wow64!Wow64NotifyDebugger+0x9
00000000`0016e1c0 00000000`6b006866 wow64!Wow64KiRaiseException+0x172
00000000`0016e530 00000000`78b83c7d wow64!Wow64SystemServiceEx+0xd6
00000000`0016edf0 00000000`6b006a5a wow64cpu!ServiceNoTurbo+0x28
00000000`0016ee80 00000000`6b005e0d wow64!RunCpuSimulation+0xa
00000000`0016eeb0 00000000`77ed8030 wow64!Wow64LdrpInitialize+0x2ed
00000000`0016f3f0 00000000`77ed582f ntdll!LdrpInitializeProcess+0x1538
00000000`0016f6f0 00000000`77ef30a5 ntdll!LdrpInitialize+0x18f
00000000`0016f7d0 00000000`7d4d1510 ntdll!KiUserApcDispatcher+0x15
00000000`0016fcc8 00000000`00000000 kernel32!BaseProcessStartThunk
00000000`0016fcd0 00000000`00000000 0x0
00000000`0016fcd8 00000000`00000000 0x0
00000000`0016fce0 00000000`00000000 0x0
00000000`0016fce8 00000000`00000000 0x0
00000000`0016fcf0 00000000`00000000 0x0
00000000`0016fcf8 00000000`00000000 0x0
00000000`0016fd00 00010007`00000000 0x0
00000000`0016fd08 00000000`00000000 0x10007`00000000
00000000`0016fd10 00000000`00000000 0x0
00000000`0016fd18 00000000`00000000 0x0

   1  Id: 2088.280c Suspend: 1 Teb: 00000000`7efd8000 Unfrozen
Child-SP          RetAddr           Call Site
00000000`0200f0d8 00000000`6b006a5a wow64cpu!WaitForMultipleObjects32+0x3a
00000000`0200f180 00000000`6b005e0d wow64!RunCpuSimulation+0xa
00000000`0200f1b0 00000000`77f109f0 wow64!Wow64LdrpInitialize+0x2ed
00000000`0200f6f0 00000000`77ef30a5 ntdll!LdrpInitialize+0x2aa
00000000`0200f7d0 00000000`7d4d1504 ntdll!KiUserApcDispatcher+0x15
00000000`0200fcc8 00000000`00000000 kernel32!BaseThreadStartThunk
00000000`0200fcd0 00000000`00000000 0x0
00000000`0200fcd8 00000000`00000000 0x0
00000000`0200fce0 00000000`00000000 0x0
00000000`0200fce8 00000000`00000000 0x0
00000000`0200fcf0 00000000`00000000 0x0
00000000`0200fcf8 00000000`00000000 0x0
00000000`0200fd00 0001002f`00000000 0x0
00000000`0200fd08 00000000`00000000 0x1002f`00000000
00000000`0200fd10 00000000`00000000 0x0
00000000`0200fd18 00000000`00000000 0x0
00000000`0200fd20 00000000`00000000 0x0
00000000`0200fd28 00000000`00000000 0x0
00000000`0200fd30 00000000`00000000 0x0
00000000`0200fd38 00000000`00000000 0x0

   2  Id: 2088.1160 Suspend: 1 Teb: 00000000`7efd5000 Unfrozen
Child-SP          RetAddr           Call Site
00000000`0272e7c8 00000000`6b29c464 wow64win!ZwUserGetMessage+0xa
00000000`0272e7d0 00000000`6b006866 wow64win!whNtUserGetMessage+0x34
00000000`0272e830 00000000`78b83c7d wow64!Wow64SystemServiceEx+0xd6
00000000`0272f0f0 00000000`6b006a5a wow64cpu!ServiceNoTurbo+0x28
00000000`0272f180 00000000`6b005e0d wow64!RunCpuSimulation+0xa
00000000`0272f1b0 00000000`77f109f0 wow64!Wow64LdrpInitialize+0x2ed
00000000`0272f6f0 00000000`77ef30a5 ntdll!LdrpInitialize+0x2aa
00000000`0272f7d0 00000000`7d4d1504 ntdll!KiUserApcDispatcher+0x15
00000000`0272fcc8 00000000`00000000 kernel32!BaseThreadStartThunk
00000000`0272fcd0 00000000`00000000 0x0
00000000`0272fcd8 00000000`00000000 0x0
00000000`0272fce0 00000000`00000000 0x0
00000000`0272fce8 00000000`00000000 0x0
00000000`0272fcf0 00000000`00000000 0x0
00000000`0272fcf8 00000000`00000000 0x0
00000000`0272fd00 00010003`00000000 0x0
00000000`0272fd08 00000000`00000000 0x10003`00000000
00000000`0272fd10 00000000`00000000 0x0
00000000`0272fd18 00000000`00000000 0x0
00000000`0272fd20 00000000`00000000 0x0

   3  Id: 2088.2d04 Suspend: 1 Teb: 00000000`7efad000 Unfrozen
Child-SP          RetAddr           Call Site
00000000`0289f108 00000000`78b84191 wow64cpu!CpupSyscallStub+0x9
00000000`0289f110 00000000`6b006a5a wow64cpu!Thunk2ArgNSpNSpReloadState+0x21
00000000`0289f180 00000000`6b005e0d wow64!RunCpuSimulation+0xa
00000000`0289f1b0 00000000`77f109f0 wow64!Wow64LdrpInitialize+0x2ed
00000000`0289f6f0 00000000`77ef30a5 ntdll!LdrpInitialize+0x2aa
00000000`0289f7d0 00000000`7d4d1504 ntdll!KiUserApcDispatcher+0x15
00000000`0289fcc8 00000000`00000000 kernel32!BaseThreadStartThunk
00000000`0289fcd0 00000000`00000000 0x0
00000000`0289fcd8 00000000`00000000 0x0
00000000`0289fce0 00000000`00000000 0x0
00000000`0289fce8 00000000`00000000 0x0
00000000`0289fcf0 00000000`00000000 0x0
00000000`0289fcf8 00000000`00000000 0x0
00000000`0289fd00 0001002f`00000000 0x0
00000000`0289fd08 00000000`00000000 0x1002f`00000000
00000000`0289fd10 00000000`00000000 0x0
00000000`0289fd18 00000000`00000000 0x0
00000000`0289fd20 00000000`00000000 0x0
00000000`0289fd28 00000000`00000000 0x0
00000000`0289fd30 00000000`00000000 0x0

   4  Id: 2088.15c4 Suspend: 1 Teb: 00000000`7efa4000 Unfrozen
Child-SP          RetAddr           Call Site
00000000`02def0a8 00000000`6b006a5a wow64cpu!RemoveIoCompletionFault+0x41
00000000`02def180 00000000`6b005e0d wow64!RunCpuSimulation+0xa
00000000`02def1b0 00000000`77f109f0 wow64!Wow64LdrpInitialize+0x2ed
00000000`02def6f0 00000000`77ef30a5 ntdll!LdrpInitialize+0x2aa
00000000`02def7d0 00000000`7d4d1504 ntdll!KiUserApcDispatcher+0x15
00000000`02defcc8 00000000`00000000 kernel32!BaseThreadStartThunk
00000000`02defcd0 00000000`00000000 0x0
00000000`02defcd8 00000000`00000000 0x0
00000000`02defce0 00000000`00000000 0x0
00000000`02defce8 00000000`00000000 0x0
00000000`02defcf0 00000000`00000000 0x0
00000000`02defcf8 00000000`00000000 0x0
00000000`02defd00 0001002f`00000000 0x0
00000000`02defd08 00000000`00000000 0x1002f`00000000
00000000`02defd10 00000000`00000000 0x0
00000000`02defd18 00000000`00000000 0x0
00000000`02defd20 00000000`00000000 0x0
00000000`02defd28 00000000`00000000 0x0
00000000`02defd30 00000000`00000000 0x0
00000000`02defd38 00000000`00000000 0x0

This is a clear indication that the process was in fact 32-bit but the dump is 64-bit. This situation is depicted in one of my earlier posts last year:

Dumps, Debuggers and Virtualization

and we need a debugger plugin to understand virtualized CPU architecture:

Dumps, Debuggers and Virtualization refined

This crash dump pattern can be called Virtualized Process. In our case we need to load wow64exts.dll WinDbg extension and set the target processor mode to x86 by using .effmach command

0:000> .load wow64exts
0:000> .effmach x86
Effective machine: x86 compatible (x86)

Then analysis gives us more meaningful results:

0:000:x86> !analyze -v
*********************************************************
*                                                       *
*                Exception Analysis                     *
*                                                       *
*********************************************************

FAULTING_IP:
kernel32!RaiseException+53
00000000`7d4e2366 5e              pop     esi

EXCEPTION_RECORD:  ffffffffffffffff -- (.exr 0xffffffffffffffff)
ExceptionAddress: 000000007d4e2366 (kernel32!RaiseException+0x0000000000000053)
   ExceptionCode: 000006d9
  ExceptionFlags: 00000001
NumberParameters: 0

BUGCHECK_STR:  6d9

DEFAULT_BUCKET_ID:  APPLICATION_FAULT

PROCESS_NAME:  App.exe

ERROR_CODE: (NTSTATUS) 0x6d9 - There are no more endpoints available from the endpoint mapper.

NTGLOBALFLAG:  0

APPLICATION_VERIFIER_FLAGS:  0

LAST_CONTROL_TRANSFER:  from 000000007da4a631 to 000000007d4e2366

STACK_TEXT:
0012d98c 7da4a631 000006d9 00000001 00000000 kernel32!RaiseException+0x53
0012d9a4 7da4a5f7 000006d9 0012ddc4 0012dda0 rpcrt4!RpcpRaiseException+0x24
0012d9b4 7dac0140 0012da00 00000018 0024a860 rpcrt4!NdrGetBuffer+0x46
0012dda0 5f2a2fba 5f2777b8 5f2771e2 0012ddc4 rpcrt4!NdrClientCall2+0x197
0012ddbc 5f29c6a6 0024a860 00000370 00000000 hnetcfg!FwOpenDynamicFwPort+0x1d
0012de68 7db4291f 0024a860 00000370 00000002 hnetcfg!IcfOpenDynamicFwPort+0x6a
0012df00 71c043db 00000370 0012df4c 00000010 mswsock!WSPBind+0x2e3
WARNING: Frame IP not in any known module. Following frames may be wrong.
0012df24 76ed91c8 00000370 0012df4c 00000010 ws2_32+0x43db
0012df6c 76ed9128 00000370 00000002 00000000 rasapi32+0x491c8
0012df98 76ed997c 00000002 00000002 00000000 rasapi32+0x49128
0012dfc0 76ed8ac2 00000002 02c225f8 02c22688 rasapi32+0x4997c
0012dfd4 76ed89cd 02c225f8 02c22ce8 02c22f38 rasapi32+0x48ac2
0012dff0 76ed82e5 02c226b2 02c22f38 00000000 rasapi32+0x489cd
0012e010 76ed827f 02c225f8 02c22ce8 02c22f38 rasapi32+0x482e5
0012e044 76ed8bf0 02c225f8 00000000 00000000 rasapi32+0x4827f
0012e0c8 76ed844d 02c225f8 00000000 04000000 rasapi32+0x48bf0
0012e170 76ed74b5 04000000 0000232b 02c21f58 rasapi32+0x4844d
0012e200 76ed544f 02c21f58 00000000 02c21f58 rasapi32+0x474b5
0012e22c 76ed944d 00000001 00000000 02c21f58 rasapi32+0x4544f
0012e24c 76ed93a4 00000000 00000000 00000000 rasapi32+0x4944d
0012e298 76ed505f 02c22c9c 00000001 04000000 rasapi32+0x493a4
0012e2bc 7db442bf 02c22c9c 00000001 04000000 rasapi32+0x4505f
0012e2ec 7db4418b 02c22c9c 00000001 04000000 mswsock!SaBlob_Query+0x2d
0012e330 7db4407c 00000000 020243f0 020243d8 mswsock!Rnr_DoDnsLookup+0xf0
0012e5c8 71c06dc0 02c22c38 00000000 0012e680 mswsock!Dns_NSPLookupServiceNext+0x24b
0012e5e0 71c06da0 02024498 02c22c38 00000000 ws2_32+0x6dc0
0012e5fc 71c06d6a 02024560 00000000 0012e680 ws2_32+0x6da0
0012e628 71c06d08 020243f0 00000000 0012e680 ws2_32+0x6d6a
0012e648 71c08282 020243d8 00000000 0012e680 ws2_32+0x6d08
0012ef00 71c07f68 02024c98 00000002 0012ef74 ws2_32+0x8282
0012ef34 71c08433 02024c98 00000001 0012ef74 ws2_32+0x7f68
0012efa0 71c03236 02024c98 00000000 00000000 ws2_32+0x8433
0012f094 71c03340 02024c98 00000000 0012f148 ws2_32+0x3236
0012f0bc 7dab22fb 0012f0d4 00000000 0012f148 ws2_32+0x3340
0012f11c 7dab3a0e 0012f184 0026fff0 0026836c rpcrt4!IP_ADDRESS_RESOLVER::NextAddress+0x13e
0012f238 7dab3c11 0026836c 00272f38 00000402 rpcrt4!TCPOrHTTP_Open+0xdb
0012f270 7da44c85 0026836c 00271d38 00272f38 rpcrt4!TCP_Open+0x55
0012f2b8 7da44b53 00000000 00271d38 00272f38 rpcrt4!OSF_CCONNECTION::TransOpen+0x5e
0012f31c 7da447d7 0026fff0 000dbba0 00000000 rpcrt4!OSF_CCONNECTION::OpenConnectionAndBind+0xbe
0012f360 7da44720 00000000 0012f414 00000000 rpcrt4!OSF_CCALL::BindToServer+0xfa
0012f378 7da3a9df 00000000 00000000 00000000 rpcrt4!OSF_BINDING_HANDLE::InitCCallWithAssociation+0x63
0012f3f4 7da3a8dd 0012f414 0012f480 00270028 rpcrt4!OSF_BINDING_HANDLE::AllocateCCall+0x49d
0012f428 7da37a1c 0012f480 0012f4ac 00000001 rpcrt4!OSF_BINDING_HANDLE::NegotiateTransferSyntax+0x2e
0012f440 7da3642c 0012f480 00000000 0012f460 rpcrt4!I_RpcGetBufferWithObject+0x5b
0012f450 7da37bff 0012f480 0012f86c 0012f84c rpcrt4!I_RpcGetBuffer+0xf
0012f460 7dac0140 0012f4ac 0000006c 0026fff0 rpcrt4!NdrGetBuffer+0x2e
0012f84c 766f41f1 766f24e8 766f423a 0012f86c rpcrt4!NdrClientCall2+0x197
0012f864 766f40b8 0026fff0 0012f904 0012f8e4 ntdsapi!_IDL_DRSBind+0x1c
0012f930 7d8ecaa2 002788bc 00278908 00000000 ntdsapi!DsBindWithSpnExW+0x223
0012f9b0 7d8ed028 00000000 02264f90 00000000 secur32!SecpTranslateName+0x1f3
0012f9d0 00434aa0 02264f90 00000000 00000002 secur32!TranslateNameW+0x2d
0012fab4 00419a7f 022a85e4 0012fc94 afec94eb App+0x34aa0
0012fb0c 0041a61b afec9443 ffffffff 00463fb8 App+0x19a7f
0012fbc0 0045a293 ffffffff 0043682f 004188f3 App+0x1a61b
0012fbc8 0043682f 004188f3 afec93eb ffffffff App+0x5a293
0012fbcc 004188f3 afec93eb ffffffff 00463fb0 App+0x3682f
0043682f 00000000 7459c085 7000c707 c3004645 App+0x188f3

STACK_COMMAND:  kb

FOLLOWUP_IP:
hnetcfg!FwOpenDynamicFwPort+1d
00000000`5f2a2fba 83c40c          add     esp,0Ch

SYMBOL_STACK_INDEX:  4

SYMBOL_NAME:  hnetcfg!FwOpenDynamicFwPort+1d

FOLLOWUP_NAME:  MachineOwner

MODULE_NAME: hnetcfg

IMAGE_NAME:  hnetcfg.dll

DEBUG_FLR_IMAGE_TIMESTAMP:  45d6cc2a

FAULTING_THREAD:  0000000000002fe4

FAILURE_BUCKET_ID:  X64_6d9_hnetcfg!FwOpenDynamicFwPort+1d

BUCKET_ID:  X64_6d9_hnetcfg!FwOpenDynamicFwPort+1d

Followup: MachineOwner
---------

0:000:x86> ~*k

.  0  Id: 2088.2fe4 Suspend: 1 Teb: 00000000`7efdb000 Unfrozen
ChildEBP          RetAddr
0012d98c 7da4a631 kernel32!RaiseException+0x53
0012d9a4 7da4a5f7 rpcrt4!RpcpRaiseException+0x24
0012d9b4 7dac0140 rpcrt4!NdrGetBuffer+0x46
0012dda0 5f2a2fba rpcrt4!NdrClientCall2+0x197
0012ddbc 5f29c6a6 hnetcfg!FwOpenDynamicFwPort+0x1d
0012de68 7db4291f hnetcfg!IcfOpenDynamicFwPort+0x6a
0012df00 71c043db mswsock!WSPBind+0x2e3
WARNING: Frame IP not in any known module. Following frames may be wrong.
0012df24 76ed91c8 ws2_32+0x43db
0012df6c 76ed9128 rasapi32+0x491c8
0012df98 76ed997c rasapi32+0x49128
0012dfc0 76ed8ac2 rasapi32+0x4997c
0012dfd4 76ed89cd rasapi32+0x48ac2
0012dff0 76ed82e5 rasapi32+0x489cd
0012e010 76ed827f rasapi32+0x482e5
0012e044 76ed8bf0 rasapi32+0x4827f
0012e0c8 76ed844d rasapi32+0x48bf0
0012e170 76ed74b5 rasapi32+0x4844d
0012e200 76ed544f rasapi32+0x474b5
0012e22c 76ed944d rasapi32+0x4544f
0012e24c 76ed93a4 rasapi32+0x4944d

   1  Id: 2088.280c Suspend: 1 Teb: 00000000`7efd8000 Unfrozen
ChildEBP          RetAddr
01fcfea4 7d63f501 ntdll_7d600000!NtWaitForMultipleObjects+0x15
01fcff48 7d63f988 ntdll_7d600000!EtwpWaitForMultipleObjectsEx+0xf7
01fcffb8 7d4dfe21 ntdll_7d600000!EtwpEventPump+0x27f
01fcffec 00000000 kernel32!BaseThreadStart+0x34

   2  Id: 2088.1160 Suspend: 1 Teb: 00000000`7efd5000 Unfrozen
ChildEBP          RetAddr
026eff50 0042f13b user32!NtUserGetMessage+0x15
WARNING: Stack unwind information not available. Following frames may be wrong.
026effb8 7d4dfe21 App+0x2f13b
026effec 00000000 kernel32!BaseThreadStart+0x34

   3  Id: 2088.2d04 Suspend: 1 Teb: 00000000`7efad000 Unfrozen
ChildEBP          RetAddr
0285ffa0 7d634d69 ntdll_7d600000!ZwDelayExecution+0x15
0285ffb8 7d4dfe21 ntdll_7d600000!RtlpTimerThread+0x47
0285ffec 00000000 kernel32!BaseThreadStart+0x34

   4  Id: 2088.15c4 Suspend: 1 Teb: 00000000`7efa4000 Unfrozen
ChildEBP          RetAddr
02daff80 7db4b6c6 ntdll_7d600000!NtRemoveIoCompletion+0x15
02daffb8 7d4dfe21 mswsock!SockAsyncThread+0x69
02daffec 00000000 kernel32!BaseThreadStart+0x34

- Dmitry Vostokov @ DumpAnalysis.org -