WinDbg exhibits a memory leak when you debug postmortem managed dumps

Howdy there!
My name is Olegas and I’ll be blogging here from time to time. Prashant has a very nice collection already and I’ll be adding my 2 cents every once in a while.

Recently I’ve come across an interesting behavior in WinDbg and I decided to look into it a bit further.

The scenario:
• You are debugging a managed dump using WinDbg 6.11.0001.404 on 32bit platform.
• You are trying to dump hundreds of managed objects to inspect their properties. You use a script similar, but not limited to
.foreach (MyObj {!dumpheap -MT 00687320 -short}) {!do MyObj}

The observed behavior:
• After dumping few dozen objects, WinDbg begins to report
<Note: this object has an invalid CLASS field>
Invalid object
• Your 32bt machine begins to respond very slowly and you notice excessive paging.
• Perfmon shows a behavior within WinDbg consistent with a memory leak
Perfmon_Graph

• If you were to look at the memory consumption of WinDbg, you will see that most of the memory is consumed by virtual allocations
0:000> !address -summary

——————– Usage SUMMARY ————————–
TotSize (      KB)   Pct(Tots) Pct(Busy)   Usage
70b24000 ( 1846416) : 88.05%    97.81%    : RegionUsageIsVAD
cc72000 (  209352) : 09.98%    00.00%    : RegionUsageFree
2e7000 (    2972) : 00.14%    00.16%    : RegionUsageImage
19000 (     100) : 00.00%    00.01%    : RegionUsageStack
4000 (      16) : 00.00%    00.00%    : RegionUsageTeb
2541000 (   38148) : 01.82%    02.02%    : RegionUsageHeap
0 (       0) : 00.00%    00.00%    : RegionUsagePageHeap
1000 (       4 ) : 00.00%    00.00%    : RegionUsagePeb
2000 (       8 ) : 00.00%    00.00%    : RegionUsageProcessParametrs
3000 (      12 ) : 00.00%    00.00%    : RegionUsageEnvironmentBlock
Tot: 7ffe1000 (2097028 KB) Busy: 7336f000 (1887676 KB)

——————– Type SUMMARY ————————–
TotSize (      KB)   Pct(Tots)  Usage
cc72000 (  209352) : 09.98%   : <free>
0 (       0) : 00.00%   : MEM_IMAGE
0 (       0) : 00.00%   : MEM_MAPPED
7336f000 ( 1887676) : 90.02%   : MEM_PRIVATE

——————– State SUMMARY ————————–
TotSize (      KB)   Pct(Tots)  Usage
7336f000 ( 1887676) : 90.02%   : MEM_COMMIT
cc72000 (  209352) : 09.98%   : MEM_FREE
0 (       0) : 00.00%   : MEM_RESERVE

Largest free region: Base 010d4000 – Size 07fca000 (130856 KB)

• The behavior remains the same whether you use SOS.dll or PSSCOR2.dll

So what’s happening here? To answer this question, we’ll attach WinDbg to an instance of WinDbg that we’ll use to recreate the problem. Based on the info from !address –summary, we’ll set a breakpoint on kernel32!VirtualAlloc
Second parameter in VirtualAlloc represents the size of the requested allocation.

When we execute the script, we’ll see that 2 allocations are made to output each managed object:
0:001> g
*********************
ChildEBP RetAddr  Args to Child
0a0cd750 6bd38e24 00000000 00040000 00001000 kernel32!VirtualAlloc
0a0cd768 6bd31b31 6bdc9b64 00000000 00040000 mscordacwks_x86_x86_2_0_50727_3620!UtilExecutionEngine::ClrVirtualAlloc+0×15
0a0cd784 6bcf6818 00000000 00040000 00001000 mscordacwks_x86_x86_2_0_50727_3620!ClrVirtualAlloc+0x1a
0a0cd7a8 6bcfdeab 7a3b3438 00000004 00000000 mscordacwks_x86_x86_2_0_50727_3620!DacInstanceManager::Alloc+0×46
0a0cd7c8 6bcfdf53 00000000 00000004 00000001 mscordacwks_x86_x86_2_0_50727_3620!DacInstantiateTypeByAddressHelper+0×77
0a0cd7e0 6bd11a7c 7a3b3438 00000004 00000001 mscordacwks_x86_x86_2_0_50727_3620!DacInstantiateTypeByAddress+0×13
0a0cd7f8 6bd14c7d 00000000 00000000 00000028 mscordacwks_x86_x86_2_0_50727_3620!ClrDataAccess::RequestUsefulGlobals+0x3c
0a0cd8a0 0b586a50 111baf58 f0000044 00000000 mscordacwks_x86_x86_2_0_50727_3620!ClrDataAccess::Request+0xbdd
WARNING: Stack unwind information not available. Following frames may be wrong.
0a0cd90c 0061061f 111baf58 0a0cd9ec 89df55fa psscor2+0x16a50
0a0cd9ac 00610889 00c64220 0a0cdbb8 0a0cdb0c dbgeng!ExtensionInfo::CallA+0x33f
0a0cdb3c 00610952 00c64220 0a0cdbb8 0a0cdbbe dbgeng!ExtensionInfo::Call+0×129
0a0cdb58 0060f14f 00c64220 00c938b0 0a0cdbb8 dbgeng!ExtensionInfo::CallAny+0×72
0a0cdfd0 006591c9 00c64220 00000000 00ffffff dbgeng!ParseBangCmd+0x65f
0a0ce0b0 0065a5c9 00c64220 00000000 89df6ca2 dbgeng!ProcessCommands+0x4f9
0a0ce0f4 0058e579 00c64220 00000000 00000001 dbgeng!ProcessCommandsAndCatch+0×49
0a0ce58c 0065a763 00c64220 0a0ceae4 00000006 dbgeng!Execute+0x2b9
0a0ce5dc 005c1f14 00c64220 00000001 89df6a4e dbgeng!ProcessCurBraceBlock+0xa3
0a0ce618 005c26da 0a0ce65c 00c64220 89df64b6 dbgeng!ProcessBlockWithTempAlias+0×44
0a0ce8e0 005c9caf 007a41e4 00c64220 007a41e4 dbgeng!DotForEach+0x78a
0a0ce8f4 0065919b 00c64220 00000000 00ffffff dbgeng!DotCommand+0x3f
eax=6bdc9b64 ebx=00040000 ecx=6bcee4a8 edx=9774fa5f esi=111baf78 edi=00000020
eip=7c809af1 esp=0a0cd754 ebp=0a0cd768 iopl=0         nv up ei pl nz na po nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000202
kernel32!VirtualAlloc:
7c809af1 8bff            mov     edi,edi
0:001> ? 00040000
Evaluate expression: 262144 = 00040000

0:001> g
*********************
ChildEBP RetAddr  Args to Child
0a0cc188 6bd38e24 00000000 001c5910 00001000 kernel32!VirtualAlloc
0a0cc1a0 6bd31b31 6bdc9b64 00000000 001c5910 mscordacwks_x86_x86_2_0_50727_3620!UtilExecutionEngine::ClrVirtualAlloc+0×15
0a0cc1bc 6bcf6818 00000000 001c5910 00001000 mscordacwks_x86_x86_2_0_50727_3620!ClrVirtualAlloc+0x1a
0a0cc1e0 6bcfdeab 7945a2d8 001c58e4 00000000 mscordacwks_x86_x86_2_0_50727_3620!DacInstanceManager::Alloc+0×46
0a0cc200 6bcfdf6a 00000000 001c58e4 00000000 mscordacwks_x86_x86_2_0_50727_3620!DacInstantiateTypeByAddressHelper+0×77
0a0cc218 6bcfc712 7945a2d8 001c58e4 00000000 mscordacwks_x86_x86_2_0_50727_3620!DacInstantiateTypeByAddressNoReport+0×13
0a0cc244 6bcf76d5 113ba5b0 00000001 6bd09e93 mscordacwks_x86_x86_2_0_50727_3620!ClrDataAccess::GetMDImport+0x4e
0a0cc250 6bd09e93 0a0cc2fc d308bb3f 6bce2b3c mscordacwks_x86_x86_2_0_50727_3620!Module::GetMDImport+0×12
0a0cc2f0 6bd0cf88 0b571250 114a4fcc 0a0cc320 mscordacwks_x86_x86_2_0_50727_3620!ClrDataModule::GetMdInterface+0×97
0a0cc30c 0b5cee00 114a4fb8 0b571250 0a0cc320 mscordacwks_x86_x86_2_0_50727_3620!ClrDataModule::QueryInterface+0×48
WARNING: Stack unwind information not available. Following frames may be wrong.
00000000 00000000 00000000 00000000 00000000 psscor2!DebugExtensionUninitialize+0xff80
eax=6bdc9b64 ebx=001c5910 ecx=6bcee4a8 edx=7945a2d8 esi=111baf78 edi=001c5900
eip=7c809af1 esp=0a0cc18c ebp=0a0cc1a0 iopl=0         nv up ei pl nz na po nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000202
kernel32!VirtualAlloc:
7c809af1 8bff            mov     edi,edi
0:001> ? 001c5910
Evaluate expression: 1857808 = 001c5910

So, we see that mscordacwks requests 2 allocations (262,144 and 1,857,808 bytes) for each object to be printed via !dumpheap. The allocations are not cleaned up and after printing a few hundred managed objects, WinDbg eventually runs out of contiguous free memory block large enough to satisfy another memory allocation necessary to dump yet another managed objects requested by the script.

Unfortunately, the only workaround at the moment it to get a list of object addressed you want to output, split them into smaller groups / batches, then print a given batch and restart WinDbg after it reaches its 2 GB limit.

Olegas

Your email address will not be published. Required fields are marked *

*