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 -

One Response to “Crash Dump Analysis Patterns (Part 129)”

  1. Dmitry Vostokov Says:

    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

Leave a Reply