Software Diagnostics Library

Here we add yet another Technology-Specific Subtrace pattern for COM client calls (as compared to COM interface invocation for servers). We recently got a complete memory dump where we had to find the destination server process, and we used the old technique described in the article In Search of Lost CID. We reprint the 32-bit stack subtrace trace here:

[...]
00faf828 7778c38b ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0x112
00faf908 776c0565 ole32!CRpcChannelBuffer::SendReceive2+0xd3
00faf974 776c04fa ole32!CAptRpcChnl::SendReceive+0xab
00faf9c8 77ce247f ole32!CCtxComChnl::SendReceive+0×1a9
00faf9e4 77ce252f RPCRT4!NdrProxySendReceive+0×43
00fafdcc 77ce25a6 RPCRT4!NdrClientCall2+0×206
[...]

Here’s also an x64 fragment from Semantic Structures (PID.TID) pattern:

[...]
00000000`018ce450 000007fe`ffee041b ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0xa3
00000000`018ce4f0 000007fe`ffd819c6 ole32!CRpcChannelBuffer::SendReceive2+0×11b
00000000`018ce6b0 000007fe`ffd81928 ole32!CAptRpcChnl::SendReceive+0×52
00000000`018ce780 000007fe`ffedfcf5 ole32!CCtxComChnl::SendReceive+0×68
00000000`018ce830 000007fe`ff56ba3b ole32!NdrExtpProxySendReceive+0×45
00000000`018ce860 000007fe`ffee02d0 RPCRT4!NdrpClientCall3+0×2e2
[...]

If we have the call over ALPC it is easy to find the server process and thread (Wait Chain). In case of a modal loop we can use raw stack analysis technique mentioned above (see also this case study).

Other subtrace examples can be found in pattern examples for High Contention (.NET CLR monitors), Wait Chain (RTL_RESOURCE), and in this case study.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

One of the questions asked was what can we do if we got a kernel memory dump instead of the requested complete memory dump? Can it be useful? Of course, if we requested a complete memory dump after analyzing a kernel memory dump then the second kernel dump may be useful for double checking. Therefore, we assume that we just got a kernel memory dump for the first time and the issue is some performance issue or system freeze and not a bugcheck. If we have a bugcheck then kernel memory dumps are sufficient most of the time, and we do not consider them for this pattern.

Such a kernel memory dump is still useful because of user space diagnostic indicators pointing to possible patterns in user space or “interspace”. We call this pattern User Space Evidence. It is a collective super-pattern like Historical Information.

We can see patterns in kernel memory dumps such as Wait Chains (for example, ALPC or Process Objects), Deadlocks (for example ALPC), kernel stack traces corresponding to specific Dual Stack Traces (for example, exception processing), Handle Leaks, Missing Threads, Module Product Process, One-Thread Processes, Spiking Thread, Process Factory (for example, PPID for Zombie Processes), and others.

Found evidence may point to specific processes and process groups (Couples Processes, session processes) and suggest process memory dump collection (especially forcing further complete memory dumps is problematic) or troubleshooting steps for diagnosed processes.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Recently we analyzed a memory dump posted in DA+TA group and posted our results there. The problem was resolved. Afterwards, we decided to look at the earlier dump that was posted for the same problem: a COM server program was unresponsive. That dump was not fully analyzed by group members so we decided to write a case study based on it since it had one more pattern.

When we open the dump in WinDbg it shows Virtualized Process (WOW64) pattern:

wow64cpu!TurboDispatchJumpAddressEnd+0x598:
00000000`77cf2772 c3 ret

We load symbols, WOW64 extension, and switch to x86 mode:

0:000> .symfix c:\mss

0:000> .reload

0:000> .load wow64exts

0:000> !sw
Switched to 32bit mode

Then we check threads in Stack Trace Collection:

0:000:x86> ~*kL

. 0 Id: 16d8.11e0 Suspend: 0 Teb: fffdc000 Unfrozen
ChildEBP RetAddr
002fb0a8 765c10fd ntdll_77d00000!NtWaitForSingleObject+0xc
002fb118 76606586 KERNELBASE!WaitForSingleObjectEx+0x99
002fb138 00499ddc KERNELBASE!GetOverlappedResult+0x9d
WARNING: Stack unwind information not available. Following frames may be wrong.
002fb1a0 005261a4 ServerA+0x99ddc
002fb1e4 005278c9 ServerA+0x1261a4
002fb454 0053bc4d ServerA+0x1278c9
002fba34 005fe5c8 ServerA+0x13bc4d
002fbe20 006094eb ServerA+0x1fe5c8
002fc40c 0060a0d7 ServerA+0x2094eb
0038ee8c 0061a0cb ServerA+0x20a0d7
0038eea4 75e65c3e ServerA+0x21a0cb
0038eed0 75edf497 rpcrt4!Invoke+0×2a
0038f55c 763b04d5 rpcrt4!NdrStubCall2+0×33c
0038f5a4 769aa572 combase!CStdStubBuffer_Invoke+0×96
0038f5c4 763b039d oleaut32!CUnivStubWrapper::Invoke+0×30
0038f650 762b3733 combase!SyncStubInvoke+0×144
(Inline) ——– combase!StubInvoke+0×9a
0038f77c 763b1198 combase!CCtxComChnl::ContextInvoke+0×222
(Inline) ——– combase!DefaultInvokeInApartment+0×4e
(Inline) ——– combase!ClassicSTAInvokeInApartment+0×103
0038f824 763b0bc2 combase!AppInvoke+0×258
0038f980 762b277e combase!ComInvokeWithLockAndIPID+0×5fb
(Inline) ——– combase!ComInvoke+0×15c
(Inline) ——– combase!ThreadDispatch+0×169
0038f9b0 75cf7834 combase!ThreadWndProc+0×2ad
0038f9dc 75cf7a9a user32!_InternalCallWinProc+0×23
0038fa6c 75cf988e user32!UserCallWinProcCheckWow+0×184
0038fad8 75d08857 user32!DispatchMessageWorker+0×208
0038fae0 0061cb88 user32!DispatchMessageA+0×10
0038ff74 0061d85a ServerA+0×21cb88
0038ff8c 7617919f ServerA+0×21d85a
0038ff98 77d4a8cb kernel32!BaseThreadInitThunk+0xe
0038ffdc 77d4a8a1 ntdll_77d00000!__RtlUserThreadStart+0×20
0038ffec 00000000 ntdll_77d00000!_RtlUserThreadStart+0×1b

1 Id: 16d8.f5c Suspend: 0 Teb: fffd9000 Unfrozen
ChildEBP RetAddr
WARNING: Frame IP not in any known module. Following frames may be wrong.
0159ff8c 7617919f 0×3b02c8
0159ff98 77d4a8cb kernel32!BaseThreadInitThunk+0xe
0159ffdc 77d4a8a1 ntdll_77d00000!__RtlUserThreadStart+0×20
0159ffec 00000000 ntdll_77d00000!_RtlUserThreadStart+0×1b

2 Id: 16d8.a88 Suspend: 0 Teb: ffe47000 Unfrozen
ChildEBP RetAddr
097cfde8 77d227d3 ntdll_77d00000!NtWaitForWorkViaWorkerFactory+0xc
097cff8c 7617919f ntdll_77d00000!TppWorkerThread+0x259
097cff98 77d4a8cb kernel32!BaseThreadInitThunk+0xe
097cffdc 77d4a8a1 ntdll_77d00000!__RtlUserThreadStart+0x20
097cffec 00000000 ntdll_77d00000!_RtlUserThreadStart+0x1b

3 Id: 16d8.ab0 Suspend: 0 Teb: fffd3000 Unfrozen
ChildEBP RetAddr
0414fde8 77d227d3 ntdll_77d00000!NtWaitForWorkViaWorkerFactory+0xc
0414ff8c 7617919f ntdll_77d00000!TppWorkerThread+0x259
0414ff98 77d4a8cb kernel32!BaseThreadInitThunk+0xe
0414ffdc 77d4a8a1 ntdll_77d00000!__RtlUserThreadStart+0x20
0414ffec 00000000 ntdll_77d00000!_RtlUserThreadStart+0x1b

4 Id: 16d8.868 Suspend: 0 Teb: ffe4d000 Unfrozen
ChildEBP RetAddr
0460fde8 77d227d3 ntdll_77d00000!NtWaitForWorkViaWorkerFactory+0xc
0460ff8c 7617919f ntdll_77d00000!TppWorkerThread+0x259
0460ff98 77d4a8cb kernel32!BaseThreadInitThunk+0xe
0460ffdc 77d4a8a1 ntdll_77d00000!__RtlUserThreadStart+0x20
0460ffec 00000000 ntdll_77d00000!_RtlUserThreadStart+0x1b

The first thread (#0) has Technology-Specific Subtrace (COM interface invocation) calling ServerA module code, and the second trace (#1) seems to be Active Thread (not waiting) having RIP Stack Trace.

However, only thread #0 seems to be Spiking Thread:

0:000:x86> !runaway f
 User Mode Time
  Thread       Time
   0:11e0      0 days 0:44:44.890
   4:868       0 days 0:00:00.000
   3:ab0       0 days 0:00:00.000
   2:a88       0 days 0:00:00.000
   1:f5c       0 days 0:00:00.000
 Kernel Mode Time
  Thread       Time
   0:11e0      0 days 0:10:38.312
   4:868       0 days 0:00:00.015
   3:ab0       0 days 0:00:00.000
   2:a88       0 days 0:00:00.000
   1:f5c       0 days 0:00:00.000
 Elapsed Time
  Thread       Time
   0:11e0      0 days 2:56:23.297
   1:f5c       0 days 2:56:22.625
   2:a88       0 days 2:54:36.883
   3:ab0       0 days 0:02:18.705
   4:868       0 days 0:01:07.372

Last Error Collection is clear but needs to be double checked by TEB32 (since we have a virtualized process):

0:000:x86> !gle
LastErrorValue: (Win32) 0 (0) - The operation completed successfully.
LastStatusValue: (NTSTATUS) 0 - STATUS_WAIT_0
Wow64 TEB status:
LastErrorValue: (Win32) 0 (0) - The operation completed successfully.
LastStatusValue: (NTSTATUS) 0 - STATUS_WAIT_0

0:000:x86> !teb
Wow64 TEB32 at 00000000fffde000
    ExceptionList:        00000000002fb108
    StackBase:            0000000000390000
    StackLimit:           0000000000255000
    SubSystemTib:         0000000000000000
    FiberData:            0000000000001e00
    ArbitraryUserPointer: 0000000000000000
    Self:                 00000000fffde000
    EnvironmentPointer:   0000000000000000
    ClientId:             00000000000016d8 . 00000000000011e0
    RpcHandle:            0000000000000000
    Tls Storage:          0000000000e12978
    PEB Address:          00000000fffdf000
    LastErrorValue:       38
    LastStatusValue:      c0000011
    Count Owned Locks:    0
    HardErrorMode:        0

Wow64 TEB at 00000000fffdc000
    ExceptionList:        00000000fffde000
    StackBase:            000000000008fd30
    StackLimit:           0000000000083000
    SubSystemTib:         0000000000000000
    FiberData:            0000000000001e00
    ArbitraryUserPointer: 0000000000000000
    Self:                 00000000fffdc000
    EnvironmentPointer:   0000000000000000
    ClientId:             00000000000016d8 . 00000000000011e0
    RpcHandle:            0000000000000000
    Tls Storage:          0000000000000000
    PEB Address:          00000000fffd6000
    LastErrorValue:       0
    LastStatusValue:      0
    Count Owned Locks:    0
    HardErrorMode:        0

From the errors we suggested to check the code dealing with EOF condition.

0:000:x86> !error 0n38
Error code: (Win32) 0x26 (38) - Reached the end of the file.

0:000:x86> !error c0000011
Error code: (NTSTATUS) 0xc0000011 (3221225489) - The end-of-file marker has been reached. There is no valid data in the file beyond this marker.

But let’s look at the thread #1 raw address and check whether we have traces of malware or JIT code or something else:

0:000:x86> ~1s
003b02c8 c20c00          ret     0Ch

0:001:x86> u 0×3b02c8
003b02c8 c20c00          ret     0Ch
003b02cb 90              nop
003b02cc cc              int     3
003b02cd cc              int     3
003b02ce cc              int     3
003b02cf cc              int     3
003b02d0 cc              int     3
003b02d1 cc              int     3

0:001:x86> ub 0x3b02c8
003b02b6 cc              int     3
003b02b7 cc              int     3
003b02b8 cc              int     3
003b02b9 cc              int     3
003b02ba cc              int     3
003b02bb cc              int     3
003b02bc b803000d00      mov     eax,0D0003h
003b02c1 64ff15c0000000  call    dword ptr fs:[0C0h]

0:001:x86> dps fs:[0C0h] L1
0053:000000c0  77cf11d8 wow64cpu!KiFastSystemCall

0:001:x86> !address 0x3b02c8

Usage:                  
Base Address:           003b0000
End Address:            003b1000
Region Size:            00001000
State:                  00001000	MEM_COMMIT
Protect:                00000020	PAGE_EXECUTE_READ
Type:                   00020000	MEM_PRIVATE
Allocation Base:        003b0000
Allocation Protect:     00000040	PAGE_EXECUTE_READWRITE

Dumping this executable region only shows WOW64 calls:

0:001:x86> dc 003b0000 003b1000
[...]

0:001:x86> .asm no_code_bytes
Assembly options: no_code_bytes

0:001:x86> u 003b0110 003b02e0
003b0110 add     byte ptr [eax],al
003b0112 add     byte ptr [eax],al
003b0114 add     byte ptr [eax],al
003b0116 add     byte ptr [eax],al
003b0118 mov     eax,3000Eh
003b011d call    dword ptr fs:[0C0h]
003b0124 ret     4
003b0127 nop
003b0128 int     3
003b0129 int     3
003b012a int     3
003b012b int     3
003b012c int     3
003b012d int     3
003b012e int     3
003b012f int     3
003b0130 int     3
003b0131 int     3
003b0132 int     3
003b0133 int     3
003b0134 mov     eax,32h
003b0139 call    dword ptr fs:[0C0h]
003b0140 ret     18h
003b0143 nop
003b0144 int     3
003b0145 int     3
003b0146 int     3
003b0147 int     3
003b0148 int     3
003b0149 int     3
003b014a int     3
003b014b int     3
003b014c int     3
003b014d int     3
003b014e int     3
003b014f int     3
003b0150 mov     eax,1B0006h
003b0155 call    dword ptr fs:[0C0h]
003b015c ret     28h
003b015f nop
003b0160 int     3
003b0161 int     3
003b0162 int     3
003b0163 int     3
003b0164 int     3
003b0165 int     3
003b0166 int     3
003b0167 int     3
003b0168 int     3
003b0169 int     3
003b016a int     3
003b016b int     3
003b016c mov     eax,7002Bh
003b0171 call    dword ptr fs:[0C0h]
003b0178 ret     8
003b017b nop
003b017c int     3
003b017d int     3
003b017e int     3
003b017f int     3
003b0180 int     3
003b0181 int     3
003b0182 int     3
003b0183 int     3
003b0184 int     3
003b0185 int     3
003b0186 int     3
003b0187 int     3
003b0188 mov     eax,17h
003b018d call    dword ptr fs:[0C0h]
003b0194 ret     18h
003b0197 nop
003b0198 int     3
003b0199 int     3
003b019a int     3
003b019b int     3
003b019c int     3
003b019d int     3
003b019e int     3
003b019f int     3
003b01a0 int     3
003b01a1 int     3
003b01a2 int     3
003b01a3 int     3
003b01a4 mov     eax,4Fh
003b01a9 call    dword ptr fs:[0C0h]
003b01b0 ret     14h
003b01b3 nop
003b01b4 int     3
003b01b5 int     3
003b01b6 int     3
003b01b7 int     3
003b01b8 int     3
003b01b9 int     3
003b01ba int     3
003b01bb int     3
003b01bc int     3
003b01bd int     3
003b01be int     3
003b01bf int     3
003b01c0 mov     eax,1Dh
003b01c5 call    dword ptr fs:[0C0h]
003b01cc ret     10h
003b01cf nop
003b01d0 int     3
003b01d1 int     3
003b01d2 int     3
003b01d3 int     3
003b01d4 int     3
003b01d5 int     3
003b01d6 int     3
003b01d7 int     3
003b01d8 int     3
003b01d9 int     3
003b01da int     3
003b01db int     3
003b01dc mov     eax,22h
003b01e1 call    dword ptr fs:[0C0h]
003b01e8 ret     18h
003b01eb nop
003b01ec int     3
003b01ed int     3
003b01ee int     3
003b01ef int     3
003b01f0 int     3
003b01f1 int     3
003b01f2 int     3
003b01f3 int     3
003b01f4 int     3
003b01f5 int     3
003b01f6 int     3
003b01f7 int     3
003b01f8 mov     eax,47h
003b01fd call    dword ptr fs:[0C0h]
003b0204 ret     14h
003b0207 nop
003b0208 int     3
003b0209 int     3
003b020a int     3
003b020b int     3
003b020c int     3
003b020d int     3
003b020e int     3
003b020f int     3
003b0210 int     3
003b0211 int     3
003b0212 int     3
003b0213 int     3
003b0214 mov     eax,1A0005h
003b0219 call    dword ptr fs:[0C0h]
003b0220 ret     24h
003b0223 nop
003b0224 int     3
003b0225 int     3
003b0226 int     3
003b0227 int     3
003b0228 int     3
003b0229 int     3
003b022a int     3
003b022b int     3
003b022c int     3
003b022d int     3
003b022e int     3
003b022f int     3
003b0230 mov     eax,10h
003b0235 call    dword ptr fs:[0C0h]
003b023c ret     14h
003b023f nop
003b0240 int     3
003b0241 int     3
003b0242 int     3
003b0243 int     3
003b0244 int     3
003b0245 int     3
003b0246 int     3
003b0247 int     3
003b0248 int     3
003b0249 int     3
003b024a int     3
003b024b int     3
003b024c mov     eax,112h
003b0251 call    dword ptr fs:[0C0h]
003b0258 ret     0Ch
003b025b nop
003b025c int     3
003b025d int     3
003b025e int     3
003b025f int     3
003b0260 int     3
003b0261 int     3
003b0262 int     3
003b0263 int     3
003b0264 int     3
003b0265 int     3
003b0266 int     3
003b0267 int     3
003b0268 mov     eax,13Eh
003b026d call    dword ptr fs:[0C0h]
003b0274 ret     0Ch
003b0277 nop
003b0278 int     3
003b0279 int     3
003b027a int     3
003b027b int     3
003b027c int     3
003b027d int     3
003b027e int     3
003b027f int     3
003b0280 int     3
003b0281 int     3
003b0282 int     3
003b0283 int     3
003b0284 mov     eax,24h
003b0289 call    dword ptr fs:[0C0h]
003b0290 ret     14h
003b0293 nop
003b0294 int     3
003b0295 int     3
003b0296 int     3
003b0297 int     3
003b0298 int     3
003b0299 int     3
003b029a int     3
003b029b int     3
003b029c int     3
003b029d int     3
003b029e int     3
003b029f int     3
003b02a0 mov     eax,18h
003b02a5 call    dword ptr fs:[0C0h]
003b02ac ret     14h
003b02af nop
003b02b0 int     3
003b02b1 int     3
003b02b2 int     3
003b02b3 int     3
003b02b4 int     3
003b02b5 int     3
003b02b6 int     3
003b02b7 int     3
003b02b8 int     3
003b02b9 int     3
003b02ba int     3
003b02bb int     3
003b02bc mov     eax,0D0003h
003b02c1 call    dword ptr fs:[0C0h]
003b02c8 ret     0Ch
003b02cb nop
003b02cc int     3
003b02cd int     3
003b02ce int     3
003b02cf int     3
003b02d0 int     3
003b02d1 int     3
003b02d2 int     3
003b02d3 int     3
003b02d4 int     3
003b02d5 int     3
003b02d6 int     3
003b02d7 int     3
003b02d8 add     byte ptr [eax],al
003b02da add     byte ptr [eax],al
003b02dc add     byte ptr [eax],al
003b02de add     byte ptr [eax],al
003b02e0 add     byte ptr [eax],al

Searching for the address of system call points to another executable region:

0:001:x86> s-d 0 L?(FFFFFFFF/4) 003b02bc
00030044 003b02bc 003b0284 71b74be0 0824448b ..;…;..K.q.D$.

0:001:x86> !address 00030044

Usage:                  
Base Address:           00030000
End Address:            00031000
Region Size:            00001000
State:                  00001000	MEM_COMMIT
Protect:                00000020	PAGE_EXECUTE_READ
Type:                   00020000	MEM_PRIVATE
Allocation Base:        00030000
Allocation Protect:     00000040	PAGE_EXECUTE_READWRITE

0:001:x86> dps 00030000 00031000
00030000 cd697e0e
00030004 4b6b72cc
00030008 036f2786
0003000c be5fe321
00030010 00000f5c
00030014 00000038
00030018 00000000
0003001c 00000030
00030020 00000000
00030024 00000001
00030028 003d0000
0003002c 003d0028
00030030 003b0000
00030034 00000000
00030038 77d4ce23 ntdll_77d00000!LdrLoadDll
0003003c 77d62fdd ntdll_77d00000!LdrUnloadDll
00030040 77d6094d ntdll_77d00000!LdrAddRefDll
00030044 003b02bc
00030048 003b0284
0003004c 71b74be0*** ERROR: Symbol file could not be found. Defaulted to export symbols for UMEngx86.dll -
UMEngx86+0×4be0
00030050 0824448b
00030054 00300589
00030058 52b8003d
0003005c e9000700
[…]

In addition to Ldr* Namespace we see a valid symbolic reference (Module Hint) to AV:

0:001:x86> u 71b74be0
UMEngx86+0x4be0:
71b74be0 push    ebp
71b74be1 mov     ebp,esp
71b74be3 push    0FFFFFFFEh
71b74be5 push    offset UMEngx86!RegQueryValueExW+0x29818 (71b9f9b8)
71b74bea push    offset UMEngx86!RegQueryValueExW+0x20b0 (71b78250)
71b74bef mov     eax,dword ptr fs:[00000000h]
71b74bf5 push    eax
71b74bf6 sub     esp,8

0:001:x86> lmv m UMEngx86
start             end                 module name
71b70000 71bae000   UMEngx86   (export symbols)       UMEngx86.dll
    Loaded symbol image file: UMEngx86.dll
    Image path: C:\ProgramData\Symantec\Symantec
        Endpoint Protection\12.1.4100.4126.105\Data\
        Definitions\BASHDefs\20150307.011\UMEngx86.dll
    Image name: UMEngx86.dll
    Timestamp:        Fri Jan 23 00:52:29 2015 (54C19B4D)
    CheckSum:         00045930
    ImageSize:        0003E000
    File version:     9.1.1.4
    Product version:  9.1.1.4
    File flags:       0 (Mask 3F)
    File OS:          4 Unknown Win32
    File type:        2.0 Dll
    File date:        00000000.00000000
    Translations:     0409.04b0
    CompanyName:      Symantec Corporation
    ProductName:      BASH
    InternalName:     UMEngx86
    OriginalFilename: UMEngx86.dll
    ProductVersion:   9.1.1.4
    FileVersion:      9.1.1.4
    FileDescription:  SONAR Engine
    LegalCopyright:   Copyright (C) 2009 - 2014 Symantec
         Corporation. All rights reserved.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

When analyzing Spiking Threads across Snapshot Collection we are interested in finding a module (or a function) that was most likely responsible (for example, “looping” inside). Here we can compare the same thread stack trace from different memory dumps and find their Variable Subtrace. For such subtraces we have changes in kv-style output: in return addresses, stack frame values, and possible arguments. The call site that starts the variable subtrace is the most likely candidate (subject to the number of snapshots). For example, consider the following pseudo code:

ModuleA!start()
{
    ModuleA!func1();
}

ModuleA!func1()
{
    ModuleB!func2();
}

ModuleB!func2()
{
    while (…)
    {
        ModuleB!func3();
    }
}

ModuleB!func3()
{
    ModuleB!func4();
}

ModuleB!func4()
{
    ModuleB!func5();
}

ModuleB!func5()
{
    // ...
}

Here, the variable stack trace part will correspond to ModuleB frames. The memory dump can be saved anywhere inside the “while” loop and down the calls, and the last variable return address down the stack trace will belong to ModuleB!func2 address range. The non-variable part will start with ModuleA!func1 address range:

// snapshot 1

RetAddr
ModuleB!func4+0×20
ModuleB!func3+0×10
ModuleB!func2+0×40
ModuleA!func1+0×10
ModuleA!start+0×300

// snapshot 2

RetAddr
ModuleB!func2+0×20
ModuleA!func1+0×10
ModuleA!start+0×300

// snapshot 3

RetAddr
ModuleB!func3+0×20
ModuleB!func2+0×40
ModuleA!func1+0×10
ModuleA!start+0×300

To illustrate this analysis pattern we adopted Memory Cell Diagram (MCD) approach from Accelerated Disassembly, Reconstruction and Reversing training and introduce here Abstract Stack Trace Notation (ASTN) diagrams where different colors are used for different modules and changes are highlighted with different fill patterns. The following three ASTN diagrams from subsequently saved process memory dumps illustrate real stack traces we analyzed some time ago. We see that the variable subtrace contains only the 3rd-party ModuleB calls. Moreover, the loop is possibly contained inside ModuleB because all ModuleA frames are non-variable including Child-SP and Args column values.

If we had ASTN diagrams below instead we would have concluded that the loop was in ModuleA with changes in ModuleB columns as an execution side effect:

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

One of the common mistakes is not double-checking symbolic output. Another example here is related to Win32 Start Address. In the output of !thread WinDbg command (or !process and !sprocess Stack Trace Collection commands) we can see Win32 Start Address and, in cases of Truncated Stack Traces or No Component Symbols, we may use this information to guess the purpose of the thread. Unfortunately, it is shown without function offsets and may give a false sense of the thread purpose. For example, this Win32 Start Address ModuleA!DoSomething may suggest that the purpose of the thread was to DoSomething:

THREAD fffffa803431cb50 Cid 03e8.2718 Teb: 000007fffff80000 Win32Thread: 0000000000000000 WAIT: (UserRequest) UserMode Non-Alertable
fffffa80330e0500 SynchronizationEvent
Impersonation token: fffff8a00b807060 (Level Impersonation)
Owning Process fffffa8032354c40 Image: ServiceA.exe
Attached Process N/A Image: N/A
Wait Start TickCount 107175 Ticks: 19677 (0:00:05:06.963)
Context Switch Count 2303 IdealProcessor: 1
UserTime 00:00:00.218
KernelTime 00:00:00.109
Win32 Start Address ModuleA!DoSomething (0×000007fef46b4cde)
Stack Init fffff88008e5fdb0 Current fffff88008e5f900
Base fffff88008e60000 Limit fffff88008e5a000 Call 0
Priority 10 BasePriority 10 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Kernel stack not resident.
Child-SP RetAddr Call Site
fffff880`08e5f940 fffff800`01c7cf72 nt!KiSwapContext+0×7a
fffff880`08e5fa80 fffff800`01c8e39f nt!KiCommitThreadWait+0×1d2
fffff880`08e5fb10 fffff800`01f7fe3e nt!KeWaitForSingleObject+0×19f
fffff880`08e5fbb0 fffff800`01c867d3 nt!NtWaitForSingleObject+0xde
fffff880`08e5fc20 00000000`76e5067a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffff880`08e5fc20)
00000000`0427cca8 000007fe`f46a4afe ntdll!NtWaitForSingleObject+0xa
00000000`0427ccb0 000007fe`f46c68d4 ModuleA!DoSomething+0xc68d4
00000000`0427cd60 000007fe`f46c6ade ModuleA!DoSomething+0xc5ee8


But if we look at fragments of the stack trace we see function huge offsets and this means that this function was just some function from ModuleA export table. It was chosen because return addresses fall into an address range between exported functions. Because Win32 Start Address also falls into such an address range it is listed as ModuleA!DoSomething but without an offset. In our case, an engineer made the wrong assumption about the possible root cause and provided unnecessary troubleshooting instructions.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Sometimes we can see signs of Crashed Processes in kernel and complete memory dumps. By crashes we mean the sudden disappearance of processes from Task Manager, for example. In memory dumps we can still see such processes as Zombie Processes. Special Processes found in the process list may help to select the possible candidate among many Zombie Processes. If a process is supposed to be launched only once (like a service) but found several times as Zombie Process and also as a normal process later in the process list (for example, as Last Object), then this may point to possible past crashes (or silent terminations). We also have a similar trace analysis pattern: Singleton Event. The following example illustrates both signs:

0: kd> !process 0 0

[...]

PROCESS fffffa80088a5640
SessionId: 0 Cid: 2184 Peb: 7fffffd7000 ParentCid: 0888
DirBase: 381b8000 ObjectTable: 00000000 HandleCount: 0.
Image: WerFault.exe

PROCESS fffffa8007254b30
SessionId: 0 Cid: 20ac Peb: 7fffffdf000 ParentCid: 02cc
DirBase: b3306000 ObjectTable: 00000000 HandleCount: 0.
Image: ServiceA.exe

[...]

PROCESS fffffa8007fe2b30
SessionId: 0 Cid: 2a1c Peb: 7fffffdf000 ParentCid: 02cc
DirBase: 11b649000 ObjectTable: fffff8a014939530 HandleCount: 112.
Image: ServiceA.exe

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Software Exception is added for completeness of pattern discourse. We mentioned it a few times before, for example, in Activation Context, Exception Module, Missing Component (static linkage), Self-Dump, Stack Overflow (software implementation), and Translated Exception patterns. Typical example of software exceptions is C++ Exception pattern.

Software exceptions, such as not enough memory, are different from the so-called hardware exceptions by being predictable, synchronous, and detected by software code itself. Hardware exceptions such as divide by zero, access violation, and memory protection, on the contrary, are unpredictable, and detected by hardware. Of course, it is possible to do some checks before code execution, and then throw a software exception or some diagnostic message for a would be hardware exception. See, for example, Self-Diagnosis pattern for user mode and its corresponding equivalent for kernel mode.

In Windows memory dumps we may see RaiseException call in user space stack trace, such as from Data Correlation pattern example:

0:000> kL
ChildEBP RetAddr
0012e950 78158e89 kernel32!RaiseException+0×53
0012e988 7830770c msvcr80!_CxxThrowException+0×46
0012e99c 783095bc mfc80u!AfxThrowMemoryException+0×19
0012e9b4 02afa8ca mfc80u!operator new+0×27
0012e9c8 02b0992f ModuleA!std::_Allocate<…>+0×1a
0012e9e0 02b09e7c ModuleA!std::vector >::vector >+0×3f
[…]

When looking for Multiple or Hidden Exceptions we may also want to check for such calls.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Corrupt Structure is added for completeness of pattern discourse. We mentioned it a few times, for example, in Self-Diagnosis (kernel mode), and Critical Section Corruption. Typical signs of the corrupt structure include:

- Regular Data such as ASCII and UNICODE fragments over substructures and pointer areas
- Large values where you expect small and vice versa
- User space address values where we expect kernel space and vice versa
- Malformed and partially zeroed _LIST_ENTRY data (see exercise C3 for linked list navigation)
- Memory read errors for pointer dereferences or inaccessible memory indicators (??)
- Memory read error at the end of the linked list while traversing structures

0: kd> dt _ERESOURCE ffffd0002299f830
ntdll!_ERESOURCE
+0x000 SystemResourcesList : _LIST_ENTRY [ 0xffffc000`07b64800 - 0xffffe000`02a79970 ]
+0x010 OwnerTable       : 0xffffe000`02a79940 _OWNER_ENTRY
+0x018 ActiveCount      : 0n0
+0x01a Flag             : 0
+0x01a ReservedLowFlags : 0 ''
+0x01b WaiterPriority   : 0 ''
+0x020 SharedWaiters    : 0x00000000`00000001 _KSEMAPHORE
+0x028 ExclusiveWaiters : 0xffffe000`02a79a58 _KEVENT
+0x030 OwnerEntry       : _OWNER_ENTRY
+0x040 ActiveEntries    : 0
+0x044 ContentionCount  : 0
+0×048 NumberOfSharedWaiters : 0×7b64800
+0×04c NumberOfExclusiveWaiters : 0xffffc000
+0×050 Reserved2        : (null)
+0×058 Address          : 0xffffd000`2299f870 Void
+0×058 CreatorBackTraceIndex : 0xffffd000`2299f870
+0×060 SpinLock         : 1

0: kd> dt _ERESOURCE ffffd0002299d830
ntdll!_ERESOURCE
+0×000 SystemResourcesList : _LIST_ENTRY [ 0×000001e0`00000280 - 0×00000000`00000004 ]
+0×010 OwnerTable       : 0×00000000`0000003c _OWNER_ENTRY
+0×018 ActiveCount      : 0n0
+0×01a Flag             : 0
+0×01a ReservedLowFlags : 0 ”
+0×01b WaiterPriority   : 0 ”
+0×020 SharedWaiters    : 0×0000003c`000001e0 _KSEMAPHORE
+0×028 ExclusiveWaiters : (null)
+0×030 OwnerEntry       : _OWNER_ENTRY
+0×040 ActiveEntries    : 0
+0×044 ContentionCount  : 0×7f
+0×048 NumberOfSharedWaiters : 0×7f
+0×04c NumberOfExclusiveWaiters : 0×7f
+0×050 Reserved2        : 0×00000001`00000001 Void
+0×058 Address          : 0×00000000`00000005 Void
+0×058 CreatorBackTraceIndex : 5
+0×060 SpinLock         : 0

However, we need to be sure that we supplied the correct pointer to dt WinDbg command. One of the signs that the pointer was incorrect are memory read errors or all zeroes:

0: kd> dt _ERESOURCE ffffd000229af830
ntdll!_ERESOURCE
+0x000 SystemResourcesList : _LIST_ENTRY [ 0x00000000`00000000 - 0x00000000`00000000 ]
+0x010 OwnerTable : (null)
+0x018 ActiveCount : 0n0
+0x01a Flag : 0
+0x01a ReservedLowFlags : 0 ''
+0x01b WaiterPriority : 0 ''
+0x020 SharedWaiters : (null)
+0x028 ExclusiveWaiters : (null)
+0x030 OwnerEntry : _OWNER_ENTRY
+0x040 ActiveEntries : 0
+0x044 ContentionCount : 0
+0x048 NumberOfSharedWaiters : 0
+0x04c NumberOfExclusiveWaiters : 0
+0x050 Reserved2 : (null)
+0x058 Address : (null)
+0x058 CreatorBackTraceIndex : 0
+0x060 SpinLock : 0

0: kd> dt _ERESOURCE ffffd00022faf830
ntdll!_ERESOURCE
+0x000 SystemResourcesList : _LIST_ENTRY
+0x010 OwnerTable       : ????
+0x018 ActiveCount      : ??
+0x01a Flag             : ??
+0x01a ReservedLowFlags : ??
+0x01b WaiterPriority   : ??
+0x020 SharedWaiters    : ????
+0x028 ExclusiveWaiters : ????
+0x030 OwnerEntry       : _OWNER_ENTRY
+0x040 ActiveEntries    : ??
+0x044 ContentionCount  : ??
+0x048 NumberOfSharedWaiters : ??
+0x04c NumberOfExclusiveWaiters : ??
+0x050 Reserved2        : ????
+0x058 Address          : ????
+0x058 CreatorBackTraceIndex : ??
+0x060 SpinLock         : ??
Memory read error ffffd00022faf890

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Sometimes, due to optimization or indeterminate stack trace reconstruction, we may not see all stack trace frames. In some case it is possible to reconstruct such Hidden Calls. For example, we have the following unmanaged Stack Trace of CLR Thread:

0:000> k
ChildEBP RetAddr
0011d6b8 66fdee7c mscorwks!JIT_IsInstanceOfClass+0xd
0011d6cc 67578500 PresentationCore_ni!`string'+0x4a2bc
0011d6e0 67578527 PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x778500)
0011d6f4 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x778527)
0011d708 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d71c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d730 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d744 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d758 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d76c 67578527 PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d780 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x778527)
0011d794 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d7a8 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d7bc 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d7d0 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d7e4 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d7f8 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d80c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d820 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d834 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d848 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d85c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d870 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d884 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d898 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d8ac 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d8c0 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d8d4 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d8e8 67578527 PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d8fc 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x778527)
0011d910 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d924 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d938 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d94c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d960 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d974 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d988 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d99c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d9b0 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d9c4 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d9d8 67578527 PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011d9ec 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x778527)
0011da00 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011da14 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011da28 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011da3c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011da50 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011da64 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011da78 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011da8c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011daa0 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011dab4 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011dac8 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011dadc 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011daf0 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011db04 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011db18 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011db2c 67578527 PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011db40 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x778527)
0011db54 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011db68 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011db7c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011db90 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011dba4 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011dbb8 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011dbcc 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011dbe0 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011dbf4 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011dc08 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011dc1c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011dc30 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011dc44 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
0011dc58 66fc3282 PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d)
*** WARNING: Unable to verify checksum for PresentationFramework.ni.dll
0011dd28 662a75e6 PresentationCore_ni!`string'+0x2e6c2
0011de08 662190a0 PresentationFramework_ni+0x2675e6
0011dffc 66fc35e2 PresentationFramework_ni+0x1d90a0
0011e0ec 66fd9dad PresentationCore_ni!`string'+0x2ea22
0011e214 66fe0459 PresentationCore_ni!`string'+0x451ed
0011e238 66fdfd40 PresentationCore_ni!`string'+0x4b899
0011e284 66fdfc9b PresentationCore_ni!`string'+0x4b180
*** WARNING: Unable to verify checksum for WindowsBase.ni.dll
0011e2b0 723ca31a PresentationCore_ni!`string'+0x4b0db
0011e2cc 723ca20a WindowsBase_ni+0x9a31a
0011e30c 723c8384 WindowsBase_ni+0x9a20a
0011e330 723cd26d WindowsBase_ni+0x98384
0011e368 723cd1f8 WindowsBase_ni+0x9d26d
0011e380 72841b4c WindowsBase_ni+0x9d1f8
0011e390 728589ec mscorwks!CallDescrWorker+0x33
0011e410 72865acc mscorwks!CallDescrWorkerWithHandler+0xa3
0011e54c 72865aff mscorwks!MethodDesc::CallDescr+0x19c
0011e568 72865b1d mscorwks!MethodDesc::CallTargetWorker+0x1f
0011e580 728bd9c8 mscorwks!MethodDescCallSite::CallWithValueTypes+0x1a
0011e74c 728bdb1e mscorwks!ExecuteCodeWithGuaranteedCleanupHelper+0x9f
*** WARNING: Unable to verify checksum for mscorlib.ni.dll
0011e7fc 68395887 mscorwks!ReflectionInvocation::ExecuteCodeWithGuaranteedCleanup+0x10f
0011e818 683804b5 mscorlib_ni+0x235887
0011e830 723cd133 mscorlib_ni+0x2204b5
0011e86c 723c7a27 WindowsBase_ni+0x9d133
0011e948 723c7d13 WindowsBase_ni+0x97a27
0011e984 723ca4fe WindowsBase_ni+0x97d13
0011e9d0 723ca42a WindowsBase_ni+0x9a4fe
0011e9f0 723ca31a WindowsBase_ni+0x9a42a
0011ea0c 723ca20a WindowsBase_ni+0x9a31a
0011ea4c 723c8384 WindowsBase_ni+0x9a20a
0011ea70 723c74e1 WindowsBase_ni+0x98384
0011eaac 723c7430 WindowsBase_ni+0x974e1
0011eadc 723c9b6c WindowsBase_ni+0x97430
0011eb2c 757462fa WindowsBase_ni+0x99b6c
0011eb58 75746d3a user32!InternalCallWinProc+0x23
0011ebd0 757477c4 user32!UserCallWinProcCheckWow+0x109
0011ec30 7574788a user32!DispatchMessageWorker+0x3bc
0011ec40 0577304e user32!DispatchMessageW+0xf
WARNING: Frame IP not in any known module. Following frames may be wrong.
0011ec5c 723c7b24 0x577304e
0011eccc 723c71f9 WindowsBase_ni+0x97b24
0011ecd8 723c719c WindowsBase_ni+0x971f9
0011ece4 6620f07e WindowsBase_ni+0x9719c
0011ecf0 6620e37f PresentationFramework_ni+0x1cf07e
0011ed14 661f56d6 PresentationFramework_ni+0x1ce37f
0011ed24 661f5699 PresentationFramework_ni+0x1b56d6
0011ed80 72841b4c PresentationFramework_ni+0x1b5699
0011eda0 72841b4c mscorwks!CallDescrWorker+0x33
0011edb0 728589ec mscorwks!CallDescrWorker+0x33
0011ee30 72865acc mscorwks!CallDescrWorkerWithHandler+0xa3
0011ef6c 72865aff mscorwks!MethodDesc::CallDescr+0x19c
0011ef88 72865b1d mscorwks!MethodDesc::CallTargetWorker+0x1f
0011efa0 728fef01 mscorwks!MethodDescCallSite::CallWithValueTypes+0x1a
0011f104 728fee21 mscorwks!ClassLoader::RunMain+0x223
0011f36c 728ff33e mscorwks!Assembly::ExecuteMainMethod+0xa6
0011f83c 728ff528 mscorwks!SystemDomain::ExecuteMainMethod+0x45e
0011f88c 728ff458 mscorwks!ExecuteEXE+0x59
0011f8d4 70aef4f3 mscorwks!_CorExeMain+0x15c
0011f90c 70b77efd mscoreei!_CorExeMain+0x10a
0011f924 70b74de3 mscoree!ShellShim__CorExeMain+0x7d
0011f92c 754c338a mscoree!_CorExeMain_Exported+0x8
0011f938 77659f72 kernel32!BaseThreadInitThunk+0xe
0011f978 77659f45 ntdll!__RtlUserThreadStart+0x70
0011f990 00000000 ntdll!_RtlUserThreadStart+0x1b

Its Managed Stack Trace is the following:

0:000> !CLRStack
OS Thread Id: 0x1520 (0)
ESP       EIP
0011e7a0 728493a4 [HelperMethodFrame_PROTECTOBJ: 0011e7a0] System.Runtime.CompilerServices.RuntimeHelpers.ExecuteCodeWithGuaranteedCleanup(TryCode, CleanupCode, System.Object)
0011e808 68395887 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
0011e824 683804b5 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
0011e83c 723cd133 System.Windows.Threading.DispatcherOperation.Invoke()
0011e874 723c7a27 System.Windows.Threading.Dispatcher.ProcessQueue()
0011e950 723c7d13 System.Windows.Threading.Dispatcher.WndProcHook(IntPtr, Int32, IntPtr, IntPtr, Boolean ByRef)
0011e99c 723ca4fe MS.Win32.HwndWrapper.WndProc(IntPtr, Int32, IntPtr, IntPtr, Boolean ByRef)
0011e9e8 723ca42a MS.Win32.HwndSubclass.DispatcherCallbackOperation(System.Object)
0011e9f8 723ca31a System.Windows.Threading.ExceptionWrapper.InternalRealCall(System.Delegate, System.Object, Boolean)
0011ea1c 723ca20a System.Windows.Threading.ExceptionWrapper.TryCatchWhen(System.Object, System.Delegate, System.Object, Boolean, System.Delegate)
0011ea64 723c8384 System.Windows.Threading.Dispatcher.WrappedInvoke(System.Delegate, System.Object, Boolean, System.Delegate)
0011ea84 723c74e1 System.Windows.Threading.Dispatcher.InvokeImpl(System.Windows.Threading.DispatcherPriority, System.TimeSpan, System.Delegate, System.Object, Boolean)
0011eac8 723c7430 System.Windows.Threading.Dispatcher.Invoke(System.Windows.Threading.DispatcherPriority, System.Delegate, System.Object)
0011eaec 723c9b6c MS.Win32.HwndSubclass.SubclassWndProc(IntPtr, Int32, IntPtr, IntPtr)
0011ec74 00270b04 [NDirectMethodFrameStandalone: 0011ec74] MS.Win32.UnsafeNativeMethods.DispatchMessage(System.Windows.Interop.MSG ByRef)
0011ec84 723c7b24 System.Windows.Threading.Dispatcher.PushFrameImpl(System.Windows.Threading.DispatcherFrame)
0011ecd4 723c71f9 System.Windows.Threading.Dispatcher.PushFrame(System.Windows.Threading.DispatcherFrame)
0011ece0 723c719c System.Windows.Threading.Dispatcher.Run()
0011ecec 6620f07e System.Windows.Application.RunDispatcher(System.Object)
0011ecf8 6620e37f System.Windows.Application.RunInternal(System.Windows.Window)
0011ed1c 661f56d6 System.Windows.Application.Run(System.Windows.Window)
0011ed2c 661f5699 System.Windows.Application.Run()
[...]

Caller-n-Callee traces also don’t reveal anything more:

Thread   0
Current frame: mscorwks!JIT_IsInstanceOfClass+0xd
ChildEBP RetAddr  Caller,Callee
0011d6b8 66fdee7c (MethodDesc 0x66ee2954 +0x3c MS.Internal.DeferredElementTreeState.GetLogicalParent(System.Windows.DependencyObject, MS.Internal.DeferredElementTreeState)), calling mscorwks!JIT_IsInstanceOfClass
0011d6cc 67578500 (MethodDesc 0x66ee1270 +0x110 MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject)), calling (MethodDesc 0x66ee2954 +0 MS.Internal.DeferredElementTreeState.GetLogicalParent(System.Windows.DependencyObject, MS.Internal.DeferredElementTreeState))
0011d6e0 67578527 (MethodDesc 0x66ee1270 +0x137 MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject)), calling (MethodDesc 0x66ee1270 +0 MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject))
0011d6f4 6757850d (MethodDesc 0x66ee1270 +0x11d MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject)), calling (MethodDesc 0x66ee1270 +0 MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject))
0011d708 6757850d (MethodDesc 0x66ee1270 +0x11d MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject)), calling (MethodDesc 0x66ee1270 +0 MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject))
0011d71c 6757850d (MethodDesc 0x66ee1270 +0x11d MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject)), calling (MethodDesc 0x66ee1270 +0 MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject))
[...]

However, if we check the return address for Top Module mscorwks (66fdee7c) we will see a call possibly related to 3D processing:

0:000> k
ChildEBP RetAddr
0011d6b8 66fdee7c mscorwks!JIT_IsInstanceOfClass+0xd
0011d6cc 67578500 PresentationCore_ni!`string’+0×4a2bc
0011d6e0 67578527 PresentationCore_ni!`string’ <PERF> (PresentationCore_ni+0×778500)
0011d6f4 6757850d PresentationCore_ni!`string’ <PERF> (PresentationCore_ni+0×778527)
[…]

0:000> ub 66fdee7c
PresentationCore_ni!`string'+0x4a2a2:
66fdee62 740c            je      PresentationCore_ni!`string'+0x4a2b0 (66fdee70)
66fdee64 8bc8            mov     ecx,eax
66fdee66 8b01            mov     eax,dword ptr [ecx]
66fdee68 ff90d8030000    call    dword ptr [eax+3D8h]
66fdee6e 8bf0            mov     esi,eax
66fdee70 8bd7            mov     edx,edi
66fdee72 b998670467      mov     ecx,offset PresentationCore_ni!`string'+0xb1bd8 (67046798)
66fdee77 e82c7afaff      call   PresentationCore_ni!?System.Windows.Media.Media3D.Viewport3DVisual.PrecomputeContent@@200001+0×3c (66f868a8)

The call structure seems to be valid when we check the next return address from the stack trace (67578500):

0:000> ub 67578500
PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784e7):
675784e7 e8f4a2a0ff      call    PresentationCore_ni!?System.Windows.Media.Media3D.ScaleTransform3D.UpdateResource@@2002011280M802+0x108 (66f827e0)
PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784ec):
675784ec eb05            jmp     PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784f3) (675784f3)
PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784ee):
675784ee b801000000      mov     eax,1
PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784f3):
675784f3 85c0            test    eax,eax
PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784f5):
675784f5 74b1            je      PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784a8) (675784a8)
PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784f7):
675784f7 8bcb            mov     ecx,ebx
PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784f9):
675784f9 33d2            xor     edx,edx
PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784fb):
675784fb e84069a6ff      call    PresentationCore_ni!`string’+0×4a280 (66fdee40)

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

To complement Module patterns sub-catalogue we introduce Origin Module pattern. This is a module that may have originated the problem behavior. For example, when we look at a stack trace we may skip Top Modules due to our knowledge of the product, for example, if they are not known as Problem Modules or known as Well-Tested Modules. In case of Truncated Stack Traces we may designate bottom modules as possible problem origins. For example, for Reference Leak pattern example we may consider checking reference counting for selected modules such as ModuleA and ModuleB:

ad377ae8 +1 Dflt nt! ?? ::FNODOBFM::`string'+18f1d
nt!ObpCallPreOperationCallbacks+4e
nt!ObpPreInterceptHandleCreate+af
nt! ?? ::NNGAKEGL::`string'+2c31f
nt!ObOpenObjectByPointerWithTag+109
nt!PsOpenProcess+1a2
nt!NtOpenProcess+23
nt!KiSystemServiceCopyEnd+13
nt!KiServiceLinkage+0
ModuleA+dca63
ModuleA+b5bc
ModuleA+c9c2e
ModuleA+bae56
ModuleA+b938d
ModuleA+c0ec6
ModuleA+afce7

ad377aeb -1 Dflt nt! ?? ::FNODOBFM::`string'+4886e
nt!ObpCallPreOperationCallbacks+277
nt!ObpPreInterceptHandleCreate+af
nt! ?? ::NNGAKEGL::`string'+2c31f
nt!ObOpenObjectByPointerWithTag+109
nt!PsOpenProcess+1a2
nt!NtOpenProcess+23
nt!KiSystemServiceCopyEnd+13
nt!KiServiceLinkage+0
ModuleA+dca63
ModuleA+b5bc
ModuleA+c9c2e
ModuleA+bae56
ModuleA+b938d
ModuleA+c0ec6
ModuleA+afce7

ad377af7 +1 Dflt nt! ?? ::NNGAKEGL::`string'+1fb41
nt!ObReferenceObjectByHandle+25
ModuleA+dcade
ModuleA+b5bc
ModuleA+c9c2e
ModuleA+bae56
ModuleA+b938d
ModuleA+c0ec6
ModuleA+afce7
ModuleA+87ca
ModuleA+834a
ModuleA+a522c
ModuleA+a51b6
ModuleA+a4787
ModuleB+19c0c
ModuleB+19b28

ad377afa -1 Dflt nt! ?? ::FNODOBFM::`string'+4886e
ModuleA+dcbbe
ModuleA+b5bc
ModuleA+c9c2e
ModuleA+bae56
ModuleA+b938d
ModuleA+c0ec6
ModuleA+afce7
ModuleA+87ca
ModuleA+834a
ModuleA+a522c
ModuleA+a51b6
ModuleA+a4787
ModuleB+19c0c
ModuleB+19b28
ModuleB+b652

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Sometimes we need memory reference information not available in software traces and logs, for example, to see pointer dereferences, to follow pointers and linked structures. In such cases memory dumps saved during logging sessions may help. In case of process memory dumps we can even have several Step Dumps. Complete and kernel memory dumps may be forced after saving a log file. We call such pattern Adjoint Space:

Then we can analyze logs and memory dumps together, for example, to follow pointer data further in memory space:

There is also a reverse situation when we use logs to see past data changes before memory snapshot time (Paratext memory analysis pattern):

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Objects such as processes may be referenced internally in addition to using handles. If their reference counts are unbalanced we may have Reference Leak pattern. For example, we have an instance of thousands of Zombie Processes but we don’t see Handle Leaks from their parent processes if we analyze ParentCids:

0: kd> !process 0 0
[...]
PROCESS fffffa801009a060
SessionId: 0 Cid: 2e270 Peb: 7fffffdb000 ParentCid: 032c
DirBase: 12ba37000 ObjectTable: 00000000 HandleCount: 0.
Image: conhost.exe

PROCESS fffffa8009b7e8e0
SessionId: 1 Cid: 2e0c8 Peb: 7fffffd9000 ParentCid: 10a0
DirBase: 21653e000 ObjectTable: 00000000 HandleCount: 0.
Image: taskmgr.exe

PROCESS fffffa8009e7a450
SessionId: 0 Cid: 2e088 Peb: 7efdf000 ParentCid: 0478
DirBase: 107f02000 ObjectTable: 00000000 HandleCount: 0.
Image: AppA.exe

PROCESS fffffa8009e794b0
SessionId: 0 Cid: 2e394 Peb: 7fffffd3000 ParentCid: 032c
DirBase: 210ffc000 ObjectTable: 00000000 HandleCount: 0.
Image: conhost.exe

PROCESS fffffa8009ed4060
SessionId: 0 Cid: 2dee4 Peb: 7efdf000 ParentCid: 0478
DirBase: 11b7c7000 ObjectTable: 00000000 HandleCount: 0.
Image: AppB.exe

PROCESS fffffa800a13bb30
SessionId: 0 Cid: 2e068 Peb: 7fffffd5000 ParentCid: 032c
DirBase: 1bb8c1000 ObjectTable: 00000000 HandleCount: 0.
Image: conhost.exe

PROCESS fffffa80096f26b0
SessionId: 0 Cid: 2e320 Peb: 7efdf000 ParentCid: 0478
DirBase: 6ad4c000 ObjectTable: 00000000 HandleCount: 0.
Image: AppC.exe

PROCESS fffffa8009c44060
SessionId: 0 Cid: 2e300 Peb: 7fffffdd000 ParentCid: 032c
DirBase: 10df06000 ObjectTable: 00000000 HandleCount: 0.
Image: conhost.exe
[...]

0: kd> !object fffffa800a13bb30
Object: fffffa800a13bb30 Type: (fffffa8006cecf30) Process
ObjectHeader: fffffa800a13bb00 (new version)
HandleCount: 0 PointerCount: 1

0: kd> !object fffffa8009b7e8e0
Object: fffffa8009b7e8e0 Type: (fffffa8006cecf30) Process
ObjectHeader: fffffa8009b7e8b0 (new version)
HandleCount: 0 PointerCount: 1

Such number of processes correlates with non-paged pool usage for process structures:

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

NonPaged Paged
Tag Allocs Frees Diff Used Allocs Frees Diff Used

Proc 55488 60 55428 80328320 0 0 0 0 Process objects , Binary: nt!ps
File 51733526 51708737 24789 7150416 0 0 0 0 File objects
[…]

Here we recommend enabling object reference tracing either using gflags.exe or directly modifying registry:

Key: HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\Session Manager\kernel
Value: ObTracePoolTags
Type: REG_SZ
Data: Proc

Note: after troubleshooting or debugging please disable tracing because it consumes pool (another variant of Instrumentation Side Effect pattern and may lead to similar Insufficient Memory pattern for stack trace database):

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

NonPaged Paged
Tag Allocs Frees Diff Used Allocs Frees Diff Used

ObRt 5688634 5676109 12525 4817288240 0 0 0 0 object reference stack tracing , Binary: nt!ob
Proc 22120 101 22019 25961168 0 0 0 0 Process objects , Binary: nt!ps
[…]

After enabling tracing we collect a complete memory dump (in case of postmortem debugging) to analyze another variant of Stack Trace pattern using !obtrace WinDbg command:

0: kd> !obtrace fffffa800af9e220
Object: fffffa800af9e220
Image: AppD.exe
Sequence (+/-) Tag Stack
-------- ----- ---- ---------------------------------------------------
ad377858 +1 Dflt nt! ?? ::NNGAKEGL::`string'+21577
nt!PspAllocateProcess+185
nt!NtCreateUserProcess+4a3
nt!KiSystemServiceCopyEnd+13

ad37787d +1 Dflt nt! ?? ::FNODOBFM::`string'+18f1d
nt!NtCreateUserProcess+569
nt!KiSystemServiceCopyEnd+13

ad377882 +1 Dflt nt! ?? ::NNGAKEGL::`string'+1f9d8
nt!NtProtectVirtualMemory+119
nt!KiSystemServiceCopyEnd+13
nt!KiServiceLinkage+0
nt!RtlCreateUserStack+1e4
nt!PspAllocateThread+299
nt!NtCreateUserProcess+65d
nt!KiSystemServiceCopyEnd+13

ad377884 -1 Dflt nt! ?? ::FNODOBFM::`string'+4886e
nt!NtProtectVirtualMemory+161
nt!KiSystemServiceCopyEnd+13
nt!KiServiceLinkage+0
nt!RtlCreateUserStack+1e4
[...]

Analysis of such traces may be complicated due to Truncated Stack Traces. We plan to show one counting trick in the next pattern.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Exception Module pattern is an obvious pattern we add for pattern language completeness. It is a module or component where the actual exception happened, for example, ModuleA from this Exception Stack Trace:

9 Id: 1df4.a08 Suspend: -1 Teb: 7fff4000 Unfrozen
ChildEBP RetAddr
1022f5a8 7c90df4a ntdll!KiFastSystemCallRet
1022f5ac 7c8648a2 ntdll!ZwWaitForMultipleObjects+0xc
1022f900 7c83ab50 kernel32!UnhandledExceptionFilter+0×8b9
1022f908 7c839b39 kernel32!BaseThreadStart+0×4d
1022f930 7c9032a8 kernel32!_except_handler3+0×61
1022f954 7c90327a ntdll!ExecuteHandler2+0×26
1022fa04 7c90e48a ntdll!ExecuteHandler+0×24
1022fa04 7c812afb ntdll!KiUserExceptionDispatcher+0xe
1022fd5c 0b82e680 kernel32!RaiseException+0×53
WARNING: Stack unwind information not available. Following frames may be wrong.
1022fd94 0b82d2f2 ModuleA+0×21e640
1022fde8 7753004f ModuleA+0×21d4f2
1022fdfc 7753032f ole32!CClassCache::CDllPathEntry::CanUnload_rl+0×3b
1022ff3c 7753028b ole32!CClassCache::FreeUnused+0×70
1022ff4c 775300b5 ole32!CoFreeUnusedLibrariesEx+0×36
1022ff58 77596af5 ole32!CoFreeUnusedLibraries+0×9
1022ff6c 77566ff9 ole32!CDllHost::MTAWorkerLoop+0×25
1022ff8c 7752687c ole32!CDllHost::WorkerThread+0xc1
1022ff94 774fe3ee ole32!DLLHostThreadEntry+0xd
1022ffa8 774fe456 ole32!CRpcThread::WorkerLoop+0×1e
1022ffb4 7c80b729 ole32!CRpcThreadCache::RpcWorkerThreadEntry+0×1b
1022ffec 00000000 kernel32!BaseThreadStart+0×37

Because we have a software exception we can use backwards disassembly (ub WinDbg command) to check stack trace correctness in case of stack unwind warnings (like in Coincidental Symbolic Information pattern). Here’s another example, for recent MS Paint crash we observed, with msvcrt exception module. However, if we skip it as a Well-Tested Module, the next exception module candidate is mspaint.

0:000> kc
Call Site
ntdll!NtWaitForMultipleObjects
KERNELBASE!WaitForMultipleObjectsEx
kernel32!WaitForMultipleObjectsExImplementation
kernel32!WerpReportFaultInternal
kernel32!WerpReportFault
kernel32!BasepReportFault
kernel32!UnhandledExceptionFilter
ntdll! ?? ::FNODOBFM::`string'
ntdll!_C_specific_handler
ntdll!RtlpExecuteHandlerForException
ntdll!RtlDispatchException
ntdll!KiUserExceptionDispatch
msvcrt!memcpy
mspaint!CImgWnd::CmdCrop
mspaint!CPBView::OnImageCrop
mfc42u!_AfxDispatchCmdMsg
mfc42u!CCmdTarget::OnCmdMsg
mfc42u!CView::OnCmdMsg
mspaint!CPBView::OnCmdMsg
mfc42u!CFrameWnd::OnCmdMsg
mspaint!CGenericCommandSite::XGenericCommandSiteCommandHandler::Execute
UIRibbon!CControlUser::_ExecuteOnHandler
UIRibbon!CGenericControlUser::SetValueImpl
UIRibbon!CGenericDataSource::SetValue
UIRibbon!OfficeSpace::DataSource::SetValue
UIRibbon!OfficeSpace::FSControl::SetValue
UIRibbon!NetUI::DeferCycle::ProcessDataBindingPropertyChangeRecords
UIRibbon!NetUI::DeferCycle::HrAddDataBindingPropertyChangeRecord
UIRibbon!NetUI::Binding::SetDataSourceValue
UIRibbon!NetUI::Bindings::OnBindingPropertyChanged
UIRibbon!NetUI::Node::OnPropertyChanged
UIRibbon!FlexUI::Concept::OnPropertyChanged
UIRibbon!NetUI::Node::FExecuteCommand
UIRibbon!FlexUI::ExecuteAction::OnCommand
UIRibbon!NetUI::Node::FExecuteCommand
UIRibbon!NetUI::SimpleButton::OnEvent
UIRibbon!NetUI::Element::_DisplayNodeCallback
UIRibbon!GPCB::xwInvokeDirect
UIRibbon!GPCB::xwInvokeFull
UIRibbon!DUserSendEvent
UIRibbon!NetUI::Element::FireEvent
UIRibbon!NetUI::_FireClickEvent
UIRibbon!NetUI::SimpleButton::OnInput
UIRibbon!NetUI::Element::_DisplayNodeCallback
UIRibbon!GPCB::xwInvokeDirect
UIRibbon!GPCB::xwInvokeFull
UIRibbon!BaseMsgQ::xwProcessNL
UIRibbon!DelayedMsgQ::xwProcessDelayedNL
UIRibbon!ContextLock::~ContextLock
UIRibbon!HWndContainer::xdHandleMessage
UIRibbon!ExtraInfoWndProc
user32!UserCallWinProcCheckWow
user32!DispatchMessageWorker
mfc42u!CWinThread::PumpMessage
mfc42u!CWinThread::Run
mfc42u!AfxWinMain
mspaint!LDunscale
kernel32!BaseThreadInitThunk
ntdll!RtlUserThreadStart

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Sometimes what looks like a memory leak when we install the new product version is not really a leak. With the previous version we had 400 MB typical memory usage but suddenly we get twice as more. We shouldn’t panic but collect a process memory dump to calmly inspect it offline. We may see Dry Weight increase: the size of all module images. For some products the new release may mean complete redesign with a new more powerful framework or incorporation of the significant number of new 3rd-party components (Module Variety). Additional sign against the memory leak hypothesis is simultaneous memory usage increase for many product processes. Although, this may be some shared module with leaking code. For example, in the example below 50% of all committed memory was image memory:

0:000> !address -summary

--- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
[...]
Image                                  1806        0`19031000 ( 402.535 Mb)   4.29%    0.00%
Heap                                     72        0`02865000 (  40.395 Mb)   0.44%    0.00%
[…]

--- Type Summary (for busy) ------ RgnCount ----------- Total Size -------- %ofBusy %ofTotal
[...]
MEM_IMAGE                              2281        0`19AA8000 ( 413.000 Mb)   4.40%    0.00%
[…]

--- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
[...]
MEM_COMMIT                             2477        0`326e8000 ( 806.906 Mb)   8.76%    0.00%
[…]

WinDbg lmt command shows almost 50 new .NET components.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Sometimes Wait Chains such as involving critical sections may have a Missing Thread endpoint. But in some cases we might see a Ghost Thread whose TID was reused by subsequent thread creation in a different process. For example, critical section structure may refer to such TID as in the example below.

// Critical section from LSASS process

THREAD fffffa803431cb50 Cid 03e8.2718 Teb: 000007fffff80000 Win32Thread: 0000000000000000 WAIT: (UserRequest) UserMode Non-Alertable
fffffa80330e0500 SynchronizationEvent
Impersonation token: fffff8a00b807060 (Level Impersonation)
Owning Process            fffffa8032354c40     Image: lsass.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      107175         Ticks: 19677 (0:00:05:06.963)
Context Switch Count      2303           IdealProcessor: 1
UserTime                  00:00:00.218
KernelTime                00:00:00.109
Win32 Start Address ntdll!TppWorkerThread (0×0000000076e1f2e0)
Stack Init fffff88008e5fdb0 Current fffff88008e5f900
Base fffff88008e60000 Limit fffff88008e5a000 Call 0
Priority 10 BasePriority 10 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Kernel stack not resident.
Child-SP RetAddr Call Site
fffff880`08e5f940 fffff800`01c7cf72 nt!KiSwapContext+0×7a
fffff880`08e5fa80 fffff800`01c8e39f nt!KiCommitThreadWait+0×1d2
fffff880`08e5fb10 fffff800`01f7fe3e nt!KeWaitForSingleObject+0×19f
fffff880`08e5fbb0 fffff800`01c867d3 nt!NtWaitForSingleObject+0xde
fffff880`08e5fc20 00000000`76e5067a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffff880`08e5fc20)
00000000`0427cca8 00000000`76e4d808 ntdll!NtWaitForSingleObject+0xa
00000000`0427ccb0 00000000`76e4d6fb ntdll!RtlpWaitOnCriticalSection+0xe8
00000000`0427cd60 000007fe`f46a4afe ntdll!RtlEnterCriticalSection+0xd1
[…]

1: kd> .process /r /p fffffa8032354c40
Implicit process is now fffffa80`32353b30
Loading User Symbols

1: kd> !cs -l -o -s
-----------------------------------------
DebugInfo          = 0x0000000003475220
Critical section   = 0x0000000003377740 (+0x3377740)
LOCKED
LockCount          = 0×10
WaiterWoken        = No
OwningThread       = 0×00000000000004e4
RecursionCount     = 0×0
LockSemaphore      = 0×0
SpinCount          = 0×0000000000000000
OwningThread       = .thread fffffa80344e4c00
[…]

// The "owner" thread is from winlogon.exe

1: kd> !thread fffffa80344e4c00 3f
THREAD fffffa80344e4c00 Cid 21d0.14e4 Teb: 000007fffffae000 Win32Thread: fffff900c0998c20 WAIT: (WrUserRequest) UserMode Non-Alertable
fffffa80355817d0 SynchronizationEvent
Not impersonating
DeviceMap            fffff8a0000088f0
Owning Process       fffffa8034ff77c0       Image: winlogon.exe
[…]

A PML (Process Monitor) log was recorded before the complete memory dump was forced, and it clearly shows Glued Activity trace analysis pattern. The thread was owned by LSASS but then exited and its TID was subsequently reused by 2 other processes.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

We recently encountered Invalid Handle pattern in the context of .NET program execution. We decided to model it and wrote a small C# program:

namespace SafeHandle
{
    class Program
    {
        static void Main(string[] args)
        {
            SafeFileHandle hFile =
                 new SafeFileHandle(new IntPtr(0xDEAD), true);
            Console.WriteLine("About to close");
            Console.ReadKey();
        }
    }
}

Of course, when we execute it nothing happens. Invalid handles are ignored by default. However, to change the behavior we enabled “Enable close exception” in glags.exe:

And if we run it we get this Managed Stack Trace:

We could have detected invalid handle if we enabled Application Verifier but then we wouldn’t have Managed Code Exception.

So we load a crash dump (saved because we enabled LocalDumps) and load SOS extension:

0:002> lmv m clr
start end module name
000007fe`ed880000 000007fe`ee1eb000 clr (pdb symbols)
Loaded symbol image file: clr.dll
Image path: C:\Windows\Microsoft.NET\Framework64\v4.0.30319\clr.dll
[...]

0:002> .load C:\Windows\Microsoft.NET\Framework64\v4.0.30319\sos

0:002> !pe
Exception object: 0000000002ab5fe8
Exception type: System.Runtime.InteropServices.SEHException
Message: External component has thrown an exception.
InnerException:
StackTrace (generated):
SP IP Function
000000001B40EDD0 0000000000000000 mscorlib_ni!Microsoft.Win32.Win32Native.CloseHandle(IntPtr)+0×1
000000001B40F2F0 0000000000000000 mscorlib_ni!System.Runtime.InteropServices.SafeHandle.InternalFinalize()+0×1
000000001B40F2F0 000007FEEC62F7A6 mscorlib_ni!System.Runtime.InteropServices.SafeHandle.Finalize()+0×26

StackTraceString:
HResult: 80004005

Our unmanaged CLR Thread Exception Stack Trace is quite simple:

0:002> k
Child-SP RetAddr Call Site
00000000`1b40d6e8 000007fe`fd651430 ntdll!NtWaitForMultipleObjects+0xa
00000000`1b40d6f0 00000000`77621723 KERNELBASE!WaitForMultipleObjectsEx+0xe8
00000000`1b40d7f0 00000000`7769b5e5 kernel32!WaitForMultipleObjectsExImplementation+0xb3
00000000`1b40d880 00000000`7769b767 kernel32!WerpReportFaultInternal+0x215
00000000`1b40d920 00000000`7769b7bf kernel32!WerpReportFault+0x77
00000000`1b40d950 00000000`7769b9dc kernel32!BasepReportFault+0x1f
00000000`1b40d980 00000000`778b3398 kernel32!UnhandledExceptionFilter+0x1fc
00000000`1b40da60 00000000`778385c8 ntdll! ?? ::FNODOBFM::`string'+0x2365
00000000`1b40da90 00000000`77849d2d ntdll!_C_specific_handler+0x8c
00000000`1b40db00 00000000`778391cf ntdll!RtlpExecuteHandlerForException+0xd
00000000`1b40db30 00000000`778397c8 ntdll!RtlDispatchException+0x45a
00000000`1b40e210 00000000`778712c7 ntdll!RtlRaiseException+0x22f
00000000`1b40ebc0 000007fe`fd651873 ntdll!KiRaiseUserExceptionDispatcher+0×3a
00000000`1b40ec90 00000000`77621991 KERNELBASE!CloseHandle+0×13
00000000`1b40ecc0 000007fe`ec720418 kernel32!CloseHandleImplementation+0×3d
00000000`1b40edd0 000007fe`ed8e9e03 mscorlib_ni+0×580418
00000000`1b40eea0 000007fe`ed8e9e7e clr!CallDescrWorkerInternal+0×83
00000000`1b40eee0 000007fe`ed8ec860 clr!CallDescrWorkerWithHandler+0×4a
00000000`1b40ef20 000007fe`ed8f1a1d clr!DispatchCallSimple+0×85
00000000`1b40efb0 000007fe`ed8f19ac clr!SafeHandle::RunReleaseMethod+0×69
00000000`1b40f050 000007fe`ed8f180a clr!SafeHandle::Release+0×122
00000000`1b40f120 000007fe`eda4863e clr!SafeHandle::Dispose+0×36
00000000`1b40f190 000007fe`ec62f7a6 clr!SafeHandle::Finalize+0xa2
00000000`1b40f2f0 000007fe`ed8e9d56 mscorlib_ni+0×48f7a6
00000000`1b40f330 000007fe`eda83c4e clr!FastCallFinalizeWorker+0×6
00000000`1b40f360 000007fe`eda83bc3 clr!MethodDesc::RequiresFullSlotNumber+0×72
00000000`1b40f3a0 000007fe`eda83b0f clr!MethodTable::CallFinalizer+0xa3
00000000`1b40f3e0 000007fe`ed9fee46 clr!SVR::CallFinalizer+0×5f
00000000`1b40f420 000007fe`ed9aac5b clr!SVR::CallFinalizer+0×102
00000000`1b40f4e0 000007fe`ed8f458c clr!WKS::GCHeap::IsPromoted+0xee
00000000`1b40f520 000007fe`ed8f451a clr!Frame::Pop+0×50
00000000`1b40f560 000007fe`ed8f4491 clr!COMCustomAttribute::PopSecurityContextFrame+0×192
00000000`1b40f660 000007fe`ed9d1bfe clr!COMCustomAttribute::PopSecurityContextFrame+0xbd
00000000`1b40f6f0 000007fe`ed9d1e59 clr!ManagedThreadBase_NoADTransition+0×3f
00000000`1b40f750 000007fe`ed9533de clr!WKS::GCHeap::FinalizerThreadStart+0×193
00000000`1b40f790 00000000`776159ed clr!Thread::intermediateThreadProc+0×7d
00000000`1b40f850 00000000`7784c541 kernel32!BaseThreadInitThunk+0xd
00000000`1b40f880 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

We see that exception processing happened during object finalization. We can infer the value of the handle (may be Small Value) via disassembly if this is possible:

0:002> kn
# Child-SP RetAddr Call Site
00 00000000`1b40d6e8 000007fe`fd651430 ntdll!NtWaitForMultipleObjects+0xa
01 00000000`1b40d6f0 00000000`77621723 KERNELBASE!WaitForMultipleObjectsEx+0xe8
02 00000000`1b40d7f0 00000000`7769b5e5 kernel32!WaitForMultipleObjectsExImplementation+0xb3
03 00000000`1b40d880 00000000`7769b767 kernel32!WerpReportFaultInternal+0x215
04 00000000`1b40d920 00000000`7769b7bf kernel32!WerpReportFault+0x77
05 00000000`1b40d950 00000000`7769b9dc kernel32!BasepReportFault+0x1f
06 00000000`1b40d980 00000000`778b3398 kernel32!UnhandledExceptionFilter+0x1fc
07 00000000`1b40da60 00000000`778385c8 ntdll! ?? ::FNODOBFM::`string'+0x2365
08 00000000`1b40da90 00000000`77849d2d ntdll!_C_specific_handler+0x8c
09 00000000`1b40db00 00000000`778391cf ntdll!RtlpExecuteHandlerForException+0xd
0a 00000000`1b40db30 00000000`778397c8 ntdll!RtlDispatchException+0x45a
0b 00000000`1b40e210 00000000`778712c7 ntdll!RtlRaiseException+0x22f
0c 00000000`1b40ebc0 000007fe`fd651873 ntdll!KiRaiseUserExceptionDispatcher+0x3a
0d 00000000`1b40ec90 00000000`77621991 KERNELBASE!CloseHandle+0×13
0e 00000000`1b40ecc0 000007fe`ec720418 kernel32!CloseHandleImplementation+0×3d
0f 00000000`1b40edd0 000007fe`ed8e9e03 mscorlib_ni+0×580418
10 00000000`1b40eea0 000007fe`ed8e9e7e clr!CallDescrWorkerInternal+0×83
11 00000000`1b40eee0 000007fe`ed8ec860 clr!CallDescrWorkerWithHandler+0×4a
12 00000000`1b40ef20 000007fe`ed8f1a1d clr!DispatchCallSimple+0×85
13 00000000`1b40efb0 000007fe`ed8f19ac clr!SafeHandle::RunReleaseMethod+0×69
14 00000000`1b40f050 000007fe`ed8f180a clr!SafeHandle::Release+0×122
15 00000000`1b40f120 000007fe`eda4863e clr!SafeHandle::Dispose+0×36
16 00000000`1b40f190 000007fe`ec62f7a6 clr!SafeHandle::Finalize+0xa2
17 00000000`1b40f2f0 000007fe`ed8e9d56 mscorlib_ni+0×48f7a6
18 00000000`1b40f330 000007fe`eda83c4e clr!FastCallFinalizeWorker+0×6
19 00000000`1b40f360 000007fe`eda83bc3 clr!MethodDesc::RequiresFullSlotNumber+0×72
1a 00000000`1b40f3a0 000007fe`eda83b0f clr!MethodTable::CallFinalizer+0xa3
1b 00000000`1b40f3e0 000007fe`ed9fee46 clr!SVR::CallFinalizer+0×5f
1c 00000000`1b40f420 000007fe`ed9aac5b clr!SVR::CallFinalizer+0×102
1d 00000000`1b40f4e0 000007fe`ed8f458c clr!WKS::GCHeap::IsPromoted+0xee
1e 00000000`1b40f520 000007fe`ed8f451a clr!Frame::Pop+0×50
1f 00000000`1b40f560 000007fe`ed8f4491 clr!COMCustomAttribute::PopSecurityContextFrame+0×192
20 00000000`1b40f660 000007fe`ed9d1bfe clr!COMCustomAttribute::PopSecurityContextFrame+0xbd
21 00000000`1b40f6f0 000007fe`ed9d1e59 clr!ManagedThreadBase_NoADTransition+0×3f
22 00000000`1b40f750 000007fe`ed9533de clr!WKS::GCHeap::FinalizerThreadStart+0×193
23 00000000`1b40f790 00000000`776159ed clr!Thread::intermediateThreadProc+0×7d
24 00000000`1b40f850 00000000`7784c541 kernel32!BaseThreadInitThunk+0xd
25 00000000`1b40f880 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

0:002> .frame /c d
0d 00000000`1b40ec90 00000000`77621991 KERNELBASE!CloseHandle+0x13
rax=00000000c0000001 rbx=000000000000dead rcx=00000000009a0000
rdx=0000000000000001 rsi=000000001b40efd0 rdi=000000001b40eff8
rip=000007fefd651873 rsp=000000001b40ec90 rbp=000000001b40edf0
r8=000000001b40ce08 r9=000000001b40cf70 r10=0000000000000000
r11=0000000000000246 r12=0000000000000001 r13=0000000040000000
r14=000000001b40ef40 r15=0000000000000000
iopl=0 nv up ei pl zr na po nc
cs=0033 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000246
KERNELBASE!CloseHandle+0×13:
000007fe`fd651873 85c0 test eax,eax

0:002> ub 00000000`77621991
kernel32!CloseHandleImplementation+0×1e:
00000000`7762196e 83f9f4 cmp ecx,0FFFFFFF4h
00000000`77621971 0f83952e0100 jae kernel32!TlsGetValue+0×3ef0 (00000000`7763480c)
00000000`77621977 488bc3 mov rax,rbx
00000000`7762197a 2503000010 and eax,10000003h
00000000`7762197f 4883f803 cmp rax,3
00000000`77621983 0f847f8dfeff je kernel32!CloseHandleImplementation+0×56 (00000000`7760a708)
00000000`77621989 488bcb mov rcx,rbx
00000000`7762198c e81f000000 call kernel32!CloseHandle (00000000`776219b0)

Here we also check the value from the managed stack trace or from Execution Residue:

0:002> !CLRStack -a
OS Thread Id: 0x1390 (2)
Child SP IP Call Site
000000001b40edf8 000000007787186a [InlinedCallFrame: 000000001b40edf8] Microsoft.Win32.Win32Native.CloseHandle(IntPtr)
000000001b40edf8 000007feec720418 [InlinedCallFrame: 000000001b40edf8] Microsoft.Win32.Win32Native.CloseHandle(IntPtr)
000000001b40edd0 000007feec720418 DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr)
PARAMETERS:
<no data>

000000001b40eff8 000007feed8e9e03 [GCFrame: 000000001b40eff8]
000000001b40f148 000007feed8e9e03 [GCFrame: 000000001b40f148]
000000001b40f1f8 000007feed8e9e03 [HelperMethodFrame_1OBJ: 000000001b40f1f8] System.Runtime.InteropServices.SafeHandle.InternalFinalize()
000000001b40f2f0 000007feec62f7a6 System.Runtime.InteropServices.SafeHandle.Finalize()
PARAMETERS:
this (0x000000001b40f330) = 0×0000000002ab2d78

000000001b40f6a8 000007feed8e9d56 [DebuggerU2MCatchHandlerFrame: 000000001b40f6a8]

0:002> !dso
OS Thread Id: 0x1390 (2)
RSP/REG Object Name
000000001B40EEA0 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle
000000001B40EFD0 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle
000000001B40F038 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle
000000001B40F050 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle
000000001B40F090 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle
000000001B40F120 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle
000000001B40F190 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle
000000001B40F1B8 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle
000000001B40F240 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle
000000001B40F2F8 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle
000000001B40F330 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle
000000001B40F360 0000000002ab5e10 System.Threading.Thread
000000001B40F390 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle
000000001B40F3E0 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle
000000001B40F3F0 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle
000000001B40F430 0000000002ab58a8 Microsoft.Win32.SafeHandles.SafeViewOfFileHandle
000000001B40F4E0 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle

0:002> !do 0000000002ab2d78
Name: Microsoft.Win32.SafeHandles.SafeFileHandle
MethodTable: 000007feec88a260
EEClass: 000007feec34d340
Size: 32(0x20) bytes
File: C:\windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
MT Field Offset Type VT Attr Value Name
000007feec88a338 400060d 8 System.IntPtr 1 instance dead handle
000007feec8892b8 400060e 10 System.Int32 1 instance 3 _state
000007feec887de0 400060f 14 System.Boolean 1 instance 1 _ownsHandle
000007feec887de0 4000610 15 System.Boolean 1 instance 1 _fullyInitialized

Please note that we don’t have global application flags:

0:002> !gflag
Current NtGlobalFlag contents: 0x00000000

Here is the exception stack trace from a different crash dump when we enable Application Verifier:

0:002> !gflag
Current NtGlobalFlag contents: 0x02000100
vrf - Enable application verifier
hpa - Place heap allocations at ends of pages

0:002> k
Child-SP RetAddr Call Site
00000000`24bac4a8 00000000`77cd3072 ntdll!NtWaitForSingleObject+0xa
00000000`24bac4b0 00000000`77cd32b5 ntdll!RtlReportExceptionEx+0x1d2
00000000`24bac5a0 000007fe`fa2c26fb ntdll!RtlReportException+0xb5
00000000`24bac620 00000000`77c2a5db verifier!AVrfpVectoredExceptionHandler+0x26b
00000000`24bac6b0 00000000`77c28e62 ntdll!RtlpCallVectoredHandlers+0xa8
00000000`24bac720 00000000`77c61248 ntdll!RtlDispatchException+0x22
00000000`24bace00 000007fe`fa2bae03 ntdll!KiUserExceptionDispatch+0x2e
00000000`24bad500 000007fe`fa2c268a verifier!VerifierStopMessageEx+0x6fb
00000000`24bad850 00000000`77c2a5db verifier!AVrfpVectoredExceptionHandler+0x1fa
00000000`24bad8e0 00000000`77c28e62 ntdll!RtlpCallVectoredHandlers+0xa8
00000000`24bad950 00000000`77c297c8 ntdll!RtlDispatchException+0x22
00000000`24bae030 00000000`77c612c7 ntdll!RtlRaiseException+0x22f
00000000`24bae9e0 000007fe`fa2d2386 ntdll!KiRaiseUserExceptionDispatcher+0x3a
00000000`24baeab0 000007fe`fdbd1873 verifier!AVrfpNtClose+0xbe
00000000`24baeae0 000007fe`fa2d4031 KERNELBASE!CloseHandle+0x13
00000000`24baeb10 000007fe`fa2d40cb verifier!AVrfpCloseHandleCommon+0x95
00000000`24baeb40 00000000`77a11991 verifier!AVrfpKernelbaseCloseHandle+0x23
00000000`24baeb80 000007fe`fa2d4031 kernel32!CloseHandleImplementation+0x3d
00000000`24baec90 000007fe`fa2d409c verifier!AVrfpCloseHandleCommon+0x95
*** WARNING: Unable to verify checksum for mscorlib.ni.dll
00000000`24baecc0 000007fe`e6a40418 verifier!AVrfpKernel32CloseHandle+0x2c
00000000`24baed00 000007fe`ec0e9e03 mscorlib_ni+0x580418
00000000`24baedd0 000007fe`ec0e9e7e clr!CallDescrWorkerInternal+0x83
00000000`24baee10 000007fe`ec0ec860 clr!CallDescrWorkerWithHandler+0x4a
00000000`24baee50 000007fe`ec0f1a1d clr!DispatchCallSimple+0x85
00000000`24baeee0 000007fe`ec0f19ac clr!SafeHandle::RunReleaseMethod+0x69
00000000`24baef80 000007fe`ec0f180a clr!SafeHandle::Release+0x122
00000000`24baf050 000007fe`ec24863e clr!SafeHandle::Dispose+0x36
00000000`24baf0c0 000007fe`e694f7a6 clr!SafeHandle::Finalize+0xa2
00000000`24baf220 000007fe`ec0e9d56 mscorlib_ni+0x48f7a6
00000000`24baf260 000007fe`ec283c4e clr!FastCallFinalizeWorker+0x6
00000000`24baf290 000007fe`ec283bc3 clr!MethodDesc::RequiresFullSlotNumber+0x72
00000000`24baf2d0 000007fe`ec283b0f clr!MethodTable::CallFinalizer+0xa3
00000000`24baf310 000007fe`ec1fee46 clr!SVR::CallFinalizer+0x5f
00000000`24baf350 000007fe`ec1aac5b clr!SVR::CallFinalizer+0x102
00000000`24baf410 000007fe`ec0f458c clr!WKS::GCHeap::IsPromoted+0xee
00000000`24baf450 000007fe`ec0f451a clr!Frame::Pop+0x50
00000000`24baf490 000007fe`ec0f4491 clr!COMCustomAttribute::PopSecurityContextFrame+0x192
00000000`24baf590 000007fe`ec1d1bfe clr!COMCustomAttribute::PopSecurityContextFrame+0xbd
00000000`24baf620 000007fe`ec1d1e59 clr!ManagedThreadBase_NoADTransition+0x3f
00000000`24baf680 000007fe`ec1533de clr!WKS::GCHeap::FinalizerThreadStart+0x193
00000000`24baf6c0 000007fe`fa2d4b87 clr!Thread::intermediateThreadProc+0x7d
00000000`24baf780 00000000`77a059ed verifier!AVrfpStandardThreadFunction+0x2b
00000000`24baf7c0 00000000`77c3c541 kernel32!BaseThreadInitThunk+0xd
00000000`24baf7f0 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

0:002> !pe
There is no current managed exception on this thread

0:002> !CLRStack
OS Thread Id: 0x51e4 (2)
Child SP IP Call Site
0000000024baed28 0000000077c612fa [InlinedCallFrame: 0000000024baed28] Microsoft.Win32.Win32Native.CloseHandle(IntPtr)
0000000024baed28 000007fee6a40418 [InlinedCallFrame: 0000000024baed28] Microsoft.Win32.Win32Native.CloseHandle(IntPtr)
0000000024baed00 000007fee6a40418 DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr)
0000000024baef28 000007feec0e9e03 [GCFrame: 0000000024baef28]
0000000024baf078 000007feec0e9e03 [GCFrame: 0000000024baf078]
0000000024baf128 000007feec0e9e03 [HelperMethodFrame_1OBJ: 0000000024baf128] System.Runtime.InteropServices.SafeHandle.InternalFinalize()
0000000024baf220 000007fee694f7a6 System.Runtime.InteropServices.SafeHandle.Finalize()
0000000024baf5d8 000007feec0e9d56 [DebuggerU2MCatchHandlerFrame: 0000000024baf5d8]

0:002> !dso
OS Thread Id: 0x51e4 (2)
RSP/REG Object Name
0000000024BAEDD0 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle
0000000024BAEF00 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle
0000000024BAEF68 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle
0000000024BAEF80 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle
0000000024BAEFC0 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle
0000000024BAF050 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle
0000000024BAF0C0 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle
0000000024BAF0E8 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle
0000000024BAF170 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle
0000000024BAF228 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle
0000000024BAF260 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle
0000000024BAF290 000000000c285e10 System.Threading.Thread
0000000024BAF2C0 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle
0000000024BAF310 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle
0000000024BAF320 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle
0000000024BAF360 000000000c2858a8 Microsoft.Win32.SafeHandles.SafeViewOfFileHandle
0000000024BAF410 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle

0:002> !CLRStack -a
OS Thread Id: 0x51e4 (2)
Child SP               IP Call Site
0000000024baed28 0000000077c612fa [InlinedCallFrame: 0000000024baed28] Microsoft.Win32.Win32Native.CloseHandle(IntPtr)
0000000024baed28 000007fee6a40418 [InlinedCallFrame: 0000000024baed28] Microsoft.Win32.Win32Native.CloseHandle(IntPtr)
0000000024baed00 000007fee6a40418 DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr)
PARAMETERS:
<no data>

0000000024baef28 000007feec0e9e03 [GCFrame: 0000000024baef28]
0000000024baf078 000007feec0e9e03 [GCFrame: 0000000024baf078]
0000000024baf128 000007feec0e9e03 [HelperMethodFrame_1OBJ: 0000000024baf128] System.Runtime.InteropServices.SafeHandle.InternalFinalize()
0000000024baf220 000007fee694f7a6 System.Runtime.InteropServices.SafeHandle.Finalize()
PARAMETERS:
this (0x0000000024baf260) = 0×000000000c282d78

0000000024baf5d8 000007feec0e9d56 [DebuggerU2MCatchHandlerFrame: 0000000024baf5d8]

0:002> !do 0x000000000c282d78
Name: Microsoft.Win32.SafeHandles.SafeFileHandle
MethodTable: 000007fee6baa260
EEClass: 000007fee666d340
Size: 32(0x20) bytes
File: C:\windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
MT Field Offset Type VT Attr Value Name
000007fee6baa338 400060d 8 System.IntPtr 1 instance dead handle
000007fee6ba92b8 400060e 10 System.Int32 1 instance 3 _state
000007fee6ba7de0 400060f 14 System.Boolean 1 instance 1 _ownsHandle
000007fee6ba7de0 4000610 15 System.Boolean 1 instance 1 _fullyInitialized

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

The set of memory dumps that prompted to introduce Insufficient Memory pattern for stack trace database also prompted to include a variant of Memory Leak pattern related to regions of virtual memory address space. We created this simple modeling application:

int _tmain(int argc, _TCHAR* argv[])
{
	int i,j;

	for (i = 1; i < 1000; ++i)
	{
		for (j = 1; j < 1000; ++j)
		{
			VirtualAlloc(NULL, 0x10000, MEM_RESERVE,
                                     PAGE_EXECUTE_READWRITE);
		}
		getc(stdin);
	}
	return 0;
}

We allocated only reserved memory regions. Committing them would probably at some stage manifest Insufficient Memory patterns for committed memory and physical memory. So we took a few consecutive memory dumps and see the ever increasing number of regions allocated at greater and greater virtual addresses:

0:000> !address
[...]
*        0`04070000        0`04080000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`04080000        0`04090000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`04090000        0`040a0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`040a0000        0`040b0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`040b0000        0`040c0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`040c0000        0`040d0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`040d0000        0`040e0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`040e0000        0`040f0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`040f0000        0`04100000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`04100000        0`04110000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`04110000        0`04120000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`04120000        0`04130000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`04130000        0`04140000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`04140000        0`04260000        0`00120000             MEM_FREE    PAGE_NOACCESS                      Free
[...]

0:000> !address
[...]
*        0`2eec0000        0`2eed0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2eed0000        0`2eee0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2eee0000        0`2eef0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2eef0000        0`2ef00000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2ef00000        0`2ef10000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2ef10000        0`2ef20000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2ef20000        0`2ef30000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2ef30000        0`2ef40000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2ef40000        0`2ef50000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2ef50000        0`2ef60000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2ef60000        0`2ef70000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2ef70000        0`2ef80000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2ef80000        0`2ef90000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2ef90000        0`2efa0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2efa0000        0`2efb0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2efb0000        0`2efc0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2efc0000        0`2efd0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2efd0000        0`2efe0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2efe0000        0`2eff0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2eff0000        0`2f000000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2f000000        0`2f010000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`2f010000        0`2f170000        0`00160000             MEM_FREE    PAGE_NOACCESS                      Free
[...]

0:000> !address
[...]
*        0`697f0000        0`69800000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`69800000        0`69810000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`69810000        0`69820000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`69820000        0`69830000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`69830000        0`69840000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`69840000        0`69850000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`69850000        0`69860000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`69860000        0`69870000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`69870000        0`69880000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`69880000        0`69890000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`69890000        0`698a0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`698a0000        0`699e0000        0`00140000             MEM_FREE    PAGE_NOACCESS                      Free
[...]

0:000> !address
[...]
*        0`c08c0000        0`c08d0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`c08d0000        0`c08e0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`c08e0000        0`c08f0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`c08f0000        0`c0900000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`c0900000        0`c0910000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`c0910000        0`c0920000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`c0920000        0`c0930000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        0`c0930000        0`c0960000        0`00030000             MEM_FREE    PAGE_NOACCESS                      Free
[...]

0:000> !address
[...]
*        1`3d6a0000        1`3d6b0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        1`3d6b0000        1`3d6c0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        1`3d6c0000        1`3d6d0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        1`3d6d0000        1`3d6e0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        1`3d6e0000        1`3d6f0000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        1`3d6f0000        1`3d700000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        1`3d700000        1`3d710000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        1`3d710000        1`3d720000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        1`3d720000        1`3d730000        0`00010000 MEM_PRIVATE MEM_RESERVE                                    <unclassified>
*        1`3d730000        1`3d7a0000        0`00070000             MEM_FREE    PAGE_NOACCESS                      Free
[...]

0:000> !address -summary

--- Usage Summary ---------------- RgnCount ———– Total Size ——– %ofBusy %ofTotal
Free                                     15      7fe`c275e000 (   7.995 Tb)           99.94%
<unclassified>                        80928        1`3d193000 (   4.955 Gb)  99.86%    0.06%
Image                                    28        0`0034b000 (   3.293 Mb)   0.06%    0.00%
Stack                                     6        0`00200000 (   2.000 Mb)   0.04%    0.00%
MemoryMappedFile                          8        0`001af000 (   1.684 Mb)   0.03%    0.00%
TEB                                       2        0`00004000 (  16.000 kb)   0.00%    0.00%
PEB                                       1        0`00001000 (   4.000 kb)   0.00%    0.00%

--- Type Summary (for busy) ------ RgnCount ----------- Total Size -------- %ofBusy %ofTotal
MEM_PRIVATE                           80936        1`3d397000 (   4.957 Gb)  99.90%    0.06%
MEM_IMAGE                                29        0`0034c000 (   3.297 Mb)   0.06%    0.00%
MEM_MAPPED                                8        0`001af000 (   1.684 Mb)   0.03%    0.00%

--- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
MEM_FREE                                 15      7fe`c275e000 (   7.995 Tb)           99.94%
MEM_RESERVE                           80926        1`3d438000 (   4.957 Gb)  99.91%    0.06%
MEM_COMMIT                               47        0`0045a000 (   4.352 Mb)   0.09%    0.00%

--- Protect Summary (for commit) - RgnCount ----------- Total Size -------- %ofBusy %ofTotal
PAGE_EXECUTE_READ                         4        0`001ef000 (   1.934 Mb)   0.04%    0.00%
PAGE_READONLY                            19        0`001de000 (   1.867 Mb)   0.04%    0.00%
PAGE_READWRITE                           17        0`00080000 ( 512.000 kb)   0.01%    0.00%
PAGE_WRITECOPY                            5        0`00008000 (  32.000 kb)   0.00%    0.00%
PAGE_READWRITE|PAGE_GUARD                 2        0`00005000 (  20.000 kb)   0.00%    0.00%

--- Largest Region by Usage ----------- Base Address -------- Region Size ----------
Free                                      1`3fac7000      7fd`bdc79000 (   7.991 Tb)
<unclassified>                            0`7f0e0000        0`00f00000 (  15.000 Mb)
Image                                     0`77831000        0`00102000 (   1.008 Mb)
Stack                                     0`00170000        0`000fb000 (1004.000 kb)
MemoryMappedFile                          0`7efe5000        0`000fb000 (1004.000 kb)
TEB                                     7ff`fffdc000        0`00002000 (   8.000 kb)
PEB                                     7ff`fffd3000        0`00001000 (   4.000 kb)

Examination of such regions for Execution Residue such as Module Hint may point into further troubleshooting directions especially if live debugging is not possible.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

While working on Insufficient Memory pattern for stack trace database we noticed the expansion of certain memory regions. Of course, after some time expanding region consumes remaining free or reserved space available before some other region. Generalizing from this we may say there can be Insufficient Memory pattern variant for any region expanding region. Region expansion may also be implemented via its move into some over position in memory virtual address space. This movement also has its limits. for example, we created this modeling application and found out it stops reallocating memory long before it reaches 2,000,000,000 byte size:

int _tmain(int argc, _TCHAR* argv[])
{
	int i = 100000000;

	void *p = malloc(i);

	for (i = 200000000; i < 2000000000; i+=100000000)
	{
		p = realloc(p, i);
		getc(stdin);
	}

	return 0;
}

We took memory dumps after each loop iteration and after 6 or 8 iterations the memory size was constant and there were no further reallocations:

0:000> !heap -s
[...]
Virtual block: 0000000006370000 - 0000000006370000 (size 0000000000000000)
[...]

0:000> !address
[...]
+ 0`00550000 0`06370000 0`05e20000 MEM_FREE PAGE_NOACCESS Free
+ 0`06370000 0`1222d000 0`0bebd000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Heap [ID: 0; Handle: 0000000000310000; Type: Large block]
+ 0`1222d000 0`77710000 0`654e3000 MEM_FREE PAGE_NOACCESS Free
+ 0`77710000 0`77711000 0`00001000 MEM_IMAGE MEM_COMMIT PAGE_READONLY Image [kernel32; “C:\windows\system32\kernel32.dll”]
[…]

0:000> !heap -s
[...]
Virtual block: 0000000012230000 - 0000000012230000 (size 0000000000000000)
[...]

0:000> !address
[...]
+ 0`005d0000 0`12230000 0`11c60000 MEM_FREE PAGE_NOACCESS Free
+ 0`12230000 0`2404b000 0`11e1b000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Heap [ID: 0; Handle: 0000000000310000; Type: Large block]
+ 0`2404b000 0`77710000 0`536c5000 MEM_FREE PAGE_NOACCESS Free
+ 0`77710000 0`77711000 0`00001000 MEM_IMAGE MEM_COMMIT PAGE_READONLY Image [kernel32; “C:\windows\system32\kernel32.dll”]
[…]

0:000> !heap -s
[...]
Virtual block: 0000000024050000 - 0000000024050000 (size 0000000000000000)
[...]

0:000> !address
[...]
+ 0`00590000 0`24050000 0`23ac0000 MEM_FREE PAGE_NOACCESS Free
+ 0`24050000 0`3bdc9000 0`17d79000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Heap [ID: 0; Handle: 0000000000310000; Type: Large block]
+ 0`3bdc9000 0`77710000 0`3b947000 MEM_FREE PAGE_NOACCESS Free
+ 0`77710000 0`77711000 0`00001000 MEM_IMAGE MEM_COMMIT PAGE_READONLY Image [kernel32; “C:\windows\system32\kernel32.dll”]
[…]

We skip a few iterations and finally come to a region that will not move and not increase:

0:000> !heap -s
[...]
Virtual block: 0000000041d30000 - 0000000041d30000 (size 0000000000000000)
[...]

0:000> !address
[...]
+ 0`006c0000 0`41d30000 0`41670000 MEM_FREE PAGE_NOACCESS Free
+ 0`41d30000 0`6b8c3000 0`29b93000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Heap [ID: 0; Handle: 0000000000310000; Type: Large block]
+ 0`6b8c3000 0`77710000 0`0be4d000 MEM_FREE PAGE_NOACCESS Free
+ 0`77710000 0`77711000 0`00001000 MEM_IMAGE MEM_COMMIT PAGE_READONLY Image [kernel32; “C:\windows\system32\kernel32.dll”]
[…]

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Once we have seen a sequence of process memory dumps with the largest one almost 4GB. They were all saved from the process with growing memory consumption from 200MB initially. Initially we suspected process heap Memory Leak. However, heap statistics (!heap -s) was normal. There were not even large block allocations. The dumps were also supplied with UMDH logs but their difference only showed Memory Fluctuation and not increase. Stack Trace Collection revealed one Spiking Thread was logging a heap allocation into user mode stack trace database. We could also see that it was Distributed Spike. Inspection of address space showed large number of sequential regions of the same size with Stack Trace Database entries inside. So we concluded that it was stack trace logging Instrumentation Side Effect and advised to limit stack backtrace size in gflags.exe.

To make sure we understood that problem correctly we decided to model it. We didn’t come to the same results probably due to different logging implementation but memory dumps clearly show the possibility of Insufficient Memory pattern variant. Here’s the source code:

void foo20 (int size)
{
    free(malloc(size));
}

#define FOO(x,y) void foo##x (int size) { foo##y(size); }

FOO(19,20)
FOO(18,19)
FOO(17,18)
FOO(16,17)
FOO(15,16)
FOO(14,15)
FOO(13,14)
FOO(12,13)
FOO(11,12)
FOO(10,11)
FOO(9,10)
FOO(8,9)
FOO(7,8)
FOO(6,7)
FOO(5,6)
FOO(4,5)
FOO(3,4)
FOO(2,3)
FOO(1,2)

typedef void (*PFN) (int);

#define ARRSZ 20

PFN pfnArr[ARRSZ]  = {foo1, foo2, foo3, foo4, foo5, foo6, foo7,
    foo8, foo9, foo10, foo11, foo12, foo13, foo14,
    foo15, foo16, foo17, foo18, foo19, foo20};

int _tmain(int argc, _TCHAR* argv[])
{
    int i;

    for (i = 1; i < 1000000000; ++i) 
    {
        pfnArr[i%ARRSZ](i);
    }

    Sleep(-1); 
    return 0;
}

It allocates and then freezes heap entries of different size from 1 byte to 1,000,000,000 bytes all with different 20 possible stack traces. We choose different stack traces to increase the number of different {size, stack backtrace} pairs as several allocation of similar size having the same stack trace may be recorded only once in the database. We emulate different stack traces by calling different entries in pfnArr. Each call then leads to foo20 but the resulting stack trace depth is different. We also enabled “Create user mode stack trace database” checkbox in gflags.exe for our application called AllocFree.exe.

Then we see the expansion of Stack Trace Database regions (addresses are different because memory dumps were taken from different application runs):

0:000> !address
[...]
+ 0`00240000 0`00312000 0`000d2000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Other [Stack Trace Database]
0`00312000 0`01a37000 0`01725000 MEM_PRIVATE MEM_RESERVE Other [Stack Trace Database]
0`01a37000 0`01a40000 0`00009000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Other [Stack Trace Database]

0:000> !address
[...]
+ 0`001b0000 0`0188c000 0`016dc000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Other [Stack Trace Database]
0`0188c000 0`0188d000 0`00001000 MEM_PRIVATE MEM_RESERVE Other [Stack Trace Database]
0`0188d000 0`019b0000 0`00123000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Other [Stack Trace Database]

Heap stays the same:

0:000> !heap -s
NtGlobalFlag enables following debugging aids for new heaps:
stack back traces
LFH Key                   : 0x000000f841c4f9c0
Termination on corruption : ENABLED
           Heap     Flags   Reserv  Commit  Virt   Free  List   UCR  Virt  Lock
  Fast
                             (k)     (k)    (k)     (k) length      blocks cont.
 heap
-------------------------------------------------------------------------------
------
0000000001a40000 08000002    4096   1444   4096   1164     4     3    0      0
   LFH
External fragmentation  80 % (4 free blocks)
0000000000010000 08008000      64      4     64      1     1     1    0      0
0000000000020000 08008000      64     64     64     61     1     1    0      0
-------------------------------------------------------------------------------
------

0:000> !heap -s
NtGlobalFlag enables following debugging aids for new heaps:
stack back traces
LFH Key                   : 0x000000473a639107
Termination on corruption : ENABLED
           Heap     Flags   Reserv  Commit  Virt   Free  List   UCR  Virt  Lock
  Fast
                             (k)     (k)    (k)     (k) length      blocks cont.
 heap
-------------------------------------------------------------------------------
------
00000000019c0000 08000002    4096   1444   4096   1164     4     3    0      0
   LFH
External fragmentation  80 % (4 free blocks)
0000000000010000 08008000      64      4     64      1     1     1    0      0
0000000000020000 08008000      64     64     64     61     1     1    0      0
-------------------------------------------------------------------------------
------

But we see the thread consuming much CPU and caught while logging stack backtrace:

0:000> kc
Call Site
ntdll!RtlpStdLogCapturedStackTrace
ntdll!RtlStdLogStackTrace
ntdll!RtlLogStackBackTraceEx
ntdll!RtlpAllocateHeap
ntdll!RtlAllocateHeap
AllocFree!_heap_alloc
AllocFree!malloc
AllocFree!foo20
AllocFree!foo19
AllocFree!foo18
AllocFree!foo17
AllocFree!foo16
AllocFree!foo15
AllocFree!foo14
AllocFree!foo13
AllocFree!foo12
AllocFree!foo11
AllocFree!foo10
AllocFree!foo9
AllocFree!foo8
AllocFree!foo7
AllocFree!foo6
AllocFree!foo5
AllocFree!foo4
AllocFree!foo3
AllocFree!foo2
AllocFree!foo1
AllocFree!wmain
AllocFree!__tmainCRTStartup
kernel32!BaseThreadInitThunk
ntdll!RtlUserThreadStart

0:000> !runaway f
 User Mode Time
  Thread       Time
   0:53b8      0 days 3:22:02.354
 Kernel Mode Time
  Thread       Time
   0:53b8      0 days 0:20:39.022
 Elapsed Time
  Thread       Time
   0:53b8      0 days 10:11:23.596

If we dump some portion of the region we see recorded stack backtraces:

0:000> dps 0`0188c000-200 L200/8
00000000`0188be00 00000000`77891142 ntdll!RtlpAllocateHeap+0x33bd
00000000`0188be08 00000000`778834d8 ntdll!RtlAllocateHeap+0x16c
00000000`0188be10 00000001`3fcc13cb AllocFree!malloc+0x5b
00000000`0188be18 00000001`3fcc1015 AllocFree!foo20+0x15
00000000`0188be20 00000001`3fcc1041 AllocFree!foo19+0x11
00000000`0188be28 00000001`3fcc1061 AllocFree!foo18+0x11
00000000`0188be30 00000001`3fcc12e3 AllocFree!wmain+0x53
00000000`0188be38 00000001`3fcc156c AllocFree!__tmainCRTStartup+0x144
00000000`0188be40 00000000`777259ed kernel32!BaseThreadInitThunk+0xd
00000000`0188be48 00000000`7785c541 ntdll!RtlUserThreadStart+0x1d
00000000`0188be50 00000000`0188b1d0
00000000`0188be58 0009457d`00024fff
00000000`0188be60 00000000`77891142 ntdll!RtlpAllocateHeap+0x33bd
00000000`0188be68 00000000`778834d8 ntdll!RtlAllocateHeap+0x16c
00000000`0188be70 00000001`3fcc13cb AllocFree!malloc+0x5b
00000000`0188be78 00000001`3fcc1015 AllocFree!foo20+0x15
00000000`0188be80 00000001`3fcc1041 AllocFree!foo19+0x11
00000000`0188be88 00000001`3fcc12e3 AllocFree!wmain+0x53
00000000`0188be90 00000001`3fcc156c AllocFree!__tmainCRTStartup+0x144
00000000`0188be98 00000000`777259ed kernel32!BaseThreadInitThunk+0xd
00000000`0188bea0 00000000`7785c541 ntdll!RtlUserThreadStart+0x1d
00000000`0188bea8 00000000`00000000
00000000`0188beb0 00000000`0188b230
00000000`0188beb8 0008457e`00023fff
00000000`0188bec0 00000000`77891142 ntdll!RtlpAllocateHeap+0x33bd
00000000`0188bec8 00000000`778834d8 ntdll!RtlAllocateHeap+0x16c
00000000`0188bed0 00000001`3fcc13cb AllocFree!malloc+0x5b
00000000`0188bed8 00000001`3fcc1015 AllocFree!foo20+0x15
00000000`0188bee0 00000001`3fcc12e3 AllocFree!wmain+0x53
00000000`0188bee8 00000001`3fcc156c AllocFree!__tmainCRTStartup+0x144
00000000`0188bef0 00000000`777259ed kernel32!BaseThreadInitThunk+0xd
00000000`0188bef8 00000000`7785c541 ntdll!RtlUserThreadStart+0x1d
00000000`0188bf00 00000000`0188b280
00000000`0188bf08 001b457f`0002dfff
00000000`0188bf10 00000000`77891142 ntdll!RtlpAllocateHeap+0x33bd
00000000`0188bf18 00000000`778834d8 ntdll!RtlAllocateHeap+0x16c
00000000`0188bf20 00000001`3fcc13cb AllocFree!malloc+0x5b
00000000`0188bf28 00000001`3fcc1015 AllocFree!foo20+0x15
00000000`0188bf30 00000001`3fcc1041 AllocFree!foo19+0x11
00000000`0188bf38 00000001`3fcc1061 AllocFree!foo18+0x11
00000000`0188bf40 00000001`3fcc1081 AllocFree!foo17+0x11
00000000`0188bf48 00000001`3fcc10a1 AllocFree!foo16+0x11
00000000`0188bf50 00000001`3fcc10c1 AllocFree!foo15+0x11
00000000`0188bf58 00000001`3fcc10e1 AllocFree!foo14+0x11
00000000`0188bf60 00000001`3fcc1101 AllocFree!foo13+0x11
00000000`0188bf68 00000001`3fcc1121 AllocFree!foo12+0x11
00000000`0188bf70 00000001`3fcc1141 AllocFree!foo11+0x11
00000000`0188bf78 00000001`3fcc1161 AllocFree!foo10+0x11
00000000`0188bf80 00000001`3fcc1181 AllocFree!foo9+0x11
00000000`0188bf88 00000001`3fcc11a1 AllocFree!foo8+0x11
00000000`0188bf90 00000001`3fcc11c1 AllocFree!foo7+0x11
00000000`0188bf98 00000001`3fcc11e1 AllocFree!foo6+0x11
00000000`0188bfa0 00000001`3fcc1201 AllocFree!foo5+0x11
00000000`0188bfa8 00000001`3fcc1221 AllocFree!foo4+0x11
00000000`0188bfb0 00000001`3fcc1241 AllocFree!foo3+0x11
00000000`0188bfb8 00000001`3fcc1261 AllocFree!foo2+0x11
00000000`0188bfc0 00000001`3fcc1281 AllocFree!foo1+0x11
00000000`0188bfc8 00000001`3fcc12e3 AllocFree!wmain+0x53
00000000`0188bfd0 00000001`3fcc156c AllocFree!__tmainCRTStartup+0x144
00000000`0188bfd8 00000000`777259ed kernel32!BaseThreadInitThunk+0xd
00000000`0188bfe0 00000000`7785c541 ntdll!RtlUserThreadStart+0x1d
00000000`0188bfe8 00000000`00000000
00000000`0188bff0 00000000`00000000
00000000`0188bff8 00000000`00000000

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Most if not all Wait Chain patterns are about waiting for some synchronization objects. Stack Traces of involved threads may point to Blocking and Top modules. In some situations we may consider a module (which functions were called) itself as a pseudo-synchronization object where a module (who called it) is waiting for it to return back (to become “signaled”). All this is problem and context dependent where some intermediate modules may be Pass Through or Well-Tested. When we see module inversion, such as in the case of callbacks we may provisionally suspect some kind of a deadlock and then investigate these threads in terms of synchronization objects or their corresponding source code:

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -