Software Diagnostics Library

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 -

This entry was posted on Wednesday, February 9th, 2011 at 11:37 pm and is filed under Crash Dump Analysis, Crash Dump Patterns, Debugging, Memory Visualization. You can follow any responses to this entry through the RSS 2.0 feed. You can leave a response, or trackback from your own site.