Crash Dump Analysis Patterns (Part 129)
Sometimes added instrumentation via gflags, application and driver verifier options affect system, service or application performance and resources. I call this pattern Instrumentation Side Effect. For example, after enabling full page heap, one process on an x64 machine was growing up to 24GB and its user memory dump shows that every heap allocation was recorded in a stack trace database:
0:055> !gflag
Current NtGlobalFlag contents: 0x02000000
hpa - Place heap allocations at ends of pages
0:055> ~*kc
[...]
48 Id: 117fc.c164 Suspend: 1 Teb: 000007ff`fff52000 Unfrozen
Call Site
ntdll!ZwWaitForSingleObject
ntdll!RtlpWaitOnCriticalSection
ntdll!RtlEnterCriticalSection
verifier!AVrfpDphEnterCriticalSection
verifier!AVrfpDphPreProcessing
verifier!AVrfDebugPageHeapAllocate
ntdll!RtlDebugAllocateHeap
ntdll! ?? ::FNODOBFM::`string’
ntdll!RtlAllocateHeap
msvcrt!malloc
ModuleA!foo1
[…]
49 Id: 117fc.de80 Suspend: 1 Teb: 000007ff`fff54000 Unfrozen
Call Site
ntdll!RtlCompareMemory
ntdll!RtlpLogCapturedStackTrace
ntdll!RtlLogStackTrace
verifier!AVrfpDphPlaceOnFreeList
verifier!AVrfDebugPageHeapFree
ntdll!RtlDebugFreeHeap
ntdll! ?? ::FNODOBFM::`string’
ntdll!RtlFreeHeap
kernel32!HeapFree
msvcrt!free
ModuleB!foo2
[…]
50 Id: 117fc.3700 Suspend: 1 Teb: 000007ff`fff4e000 Unfrozen
Call Site
ntdll!ZwWaitForSingleObject
ntdll!RtlpWaitOnCriticalSection
ntdll!RtlEnterCriticalSection
verifier!AVrfpDphEnterCriticalSection
verifier!AVrfpDphPreProcessing
verifier!AVrfDebugPageHeapFree
ntdll!RtlDebugFreeHeap
ntdll! ?? ::FNODOBFM::`string’
ntdll!RtlFreeHeap
kernel32!HeapFree
msvcrt!free
ModuleC!foo3
[…]
0:055> !runaway
User Mode Time
Thread Time
38:d090 0 days 0:02:28.793
44:ca48 0 days 0:01:04.459
48:c164 0 days 0:00:56.909
43:4458 0 days 0:00:54.475
50:3700 0 days 0:00:43.992
45:6f98 0 days 0:00:38.953
49:de80 0 days 0:00:24.211
1:391c 0 days 0:00:00.639
0:7e90 0 days 0:00:00.109
55:a300 0 days 0:00:00.046
34:10c9c 0 days 0:00:00.015
21:d054 0 days 0:00:00.015
56:b0a0 0 days 0:00:00.000
54:8b78 0 days 0:00:00.000
53:155b8 0 days 0:00:00.000
52:b444 0 days 0:00:00.000
Top modules ModuleA(B, C) from the spiking and heap intensive threads are from the same vendor.
I was able to get a 200×27349 slice from that dump using ImageMagick and it shows almost all virtual memory space filled with traces of this pictorial form (magnified by x8):
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
April 10th, 2012 at 2:29 pm
Another side-effect from object tracking:
kd> !poolused 3
Sorting by NonPaged Pool Consumed
Pool Used:
NonPaged Paged
Tag Allocs Frees Diff Used Allocs Frees Diff Used
ObRt 4384299 4383686 615 54256308 0 0 0 0 object reference stack tracing , Binary: nt!ob