Introduction
This article is about debugging a memory issue in a .NET application postmortemly using Windbg and .NET debugging extension SOS. This had happened in a real production environment where user was experiencing unusual memory usage of an application and that it was just not possible for me to go into their environment to do live debugging, so majorly this is a postmortem debugging sharing.
The code that is exhibiting this issue can't be shared but I found a section from the book "Advanced .NET Debugging" that is roughly the same as my scenario. So the following content is based on the sample code from the book. But the processes are the same.
Background
One of our customers kept coming back with complaints that our application had eaten up their memory in an abnormal way. We tried several methods to look into their case but all ended up futile: log analysis, system diagnostic, system event logs analysis, etc.
One last resort we'd taken is to let them take a memory dump of the application while the symptom exhibiting using task manager and send us the dump file.
Fortunately, at the end, we were able to identify the root cause and provided the patch to our user. The process of analyzing the dump file and inspirations I got along the way led to this write-up.
Some Basic Concepts
Finalizer
At times, objects that encapsulate other resources require that these resources be cleaned up as part of object destruction. A great example is an object that wraps an underlying native resource such as a file handle. Without explicit cleanup code, the memory behind the managed object is cleaned up by the GC, but the underlying handle that the object encapsulates is not (because GC has no special knowledge of native handles).
The net result is naturally a resource leak. To provide a proper cleanup mechanism, the CLR introduces what is known as finalizers. A finalizer can be compared to destructors in the native C++ world. Whenever an object is freed (or garbage collected), the destructor (or finalizer) is run.
In C#, a finalizer is declared very similarly to a C++ destructor by using the ~<class name>() notation. An example is shown in the following listing:
public class MyClass
{
~MyClass()
{
}
}
When the class is compiled into IL, the finalize method gets translated into a function called Finalize.
To keep track of which objects have finalizers, the garbage collector maintains a queue called a finalization
queue in which all objects with finalizers that are alive on the managed heap.
When an object with a finalizer becomes rootless and a garbage collection occurs, the GC places the object(defines finalizers and considered to be garbage) on a different queue known as the f-reachable queue.
Finalizer code for each of the objects on the f-reachable queue is not executed as part of the garbage collection
phase.
Instead, each .NET process contains a special thread known as the finalization thread which GC will wake up from time to time and will execute finalizer method object after object from the queue.
After finalizer method has been executed, the objects will be removed from f-reachable queue and considered rootless, and are eligible for reclaim by GC.
Debugging Steps
First of all, to create a dump file of the faulty application:
We will use Windows built-in task manager to create the dump. One thing to keep in mind is that if the application is 32bit, then the taskmgr.exe (C:\Windows\SysWOW64\Taskmgr.exe) has to be 32bits, and Windbg.exe has to be the 32bits version as well. The same holds true for 64bit applications.
P.S.: Right now, you can only install Windbg as part of Windows SDK which is quite big, but there are standalone installers for Windbg at http://codemachine.com/downloads.html.
So dump file will be created with "Create dump file", like below:
Then, we will use Windbg to open the newly created dump file like below:
The first thing we need to do is load the .NET debugger extension by executing:
.loadby sos.dll clr
To avoid specifying the full path to the SOS debugger extension, we use .loadby. The syntax is as follows:
.loadby <extension DLL> <module name>
Where extension DLL represents the name of the debugger extension we want to load - SOS.DLL in this case. The module name represents a currently loaded module - clr in this case. The .loadby command then attempts to load the extension DLL from the same path that the module is located in.
With SOS loaded, let's first check for various private heaps associated with AppDomains and JIT heap.
0:000> !eeheap -loader
Loader Heap:
--------------------------------------
System Domain: 6ee2a288
LowFrequencyHeap: 035b0000(3000:1000) Size: 0x1000 (4096) bytes.
HighFrequencyHeap: 035b4000(9000:1000) Size: 0x1000 (4096) bytes.
StubHeap: 035bd000(3000:1000) Size: 0x1000 (4096) bytes.
Virtual Call Stub Heap:
IndcellHeap: 03920000(2000:1000) Size: 0x1000 (4096) bytes.
LookupHeap: 03925000(2000:1000) Size: 0x1000 (4096) bytes.
ResolveHeap: 0392b000(5000:1000) Size: 0x1000 (4096) bytes.
DispatchHeap: 03927000(4000:1000) Size: 0x1000 (4096) bytes.
CacheEntryHeap: Size: 0x0 (0) bytes.
Total size: Size: 0x7000 (28672) bytes.
--------------------------------------
Shared Domain: 6ee29f38
LowFrequencyHeap: 035b0000(3000:1000) Size: 0x1000 (4096) bytes.
HighFrequencyHeap: 035b4000(9000:1000) Size: 0x1000 (4096) bytes.
StubHeap: 035bd000(3000:1000) Size: 0x1000 (4096) bytes.
Virtual Call Stub Heap:
IndcellHeap: 03920000(2000:1000) Size: 0x1000 (4096) bytes.
LookupHeap: 03925000(2000:1000) Size: 0x1000 (4096) bytes.
ResolveHeap: 0392b000(5000:1000) Size: 0x1000 (4096) bytes.
DispatchHeap: 03927000(4000:1000) Size: 0x1000 (4096) bytes.
CacheEntryHeap: Size: 0x0 (0) bytes.
Total size: Size: 0x7000 (28672) bytes.
--------------------------------------
Domain 1: 035f2320
LowFrequencyHeap: 035c0000(3000:3000) Size: 0x3000 (12288) bytes.
HighFrequencyHeap: 035c3000(a000:5000) Size: 0x5000 (20480) bytes.
StubHeap: Size: 0x0 (0) bytes.
Virtual Call Stub Heap:
IndcellHeap: Size: 0x0 (0) bytes.
LookupHeap: Size: 0x0 (0) bytes.
ResolveHeap: 0391a000(6000:1000) Size: 0x1000 (4096) bytes.
DispatchHeap: 03917000(3000:1000) Size: 0x1000 (4096) bytes.
CacheEntryHeap: 03912000(4000:1000) Size: 0x1000 (4096) bytes.
Total size: Size: 0xb000 (45056) bytes.
--------------------------------------
Jit code heap:
LoaderCodeHeap: 00000000(0:0) Size: 0x0 (0) bytes.
Total size: Size: 0x0 (0) bytes.
--------------------------------------
Module Thunk heaps:
Module 6d311000: Size: 0x0 (0) bytes.
Module 035c4014: Size: 0x0 (0) bytes.
Module 51621000: Size: 0x0 (0) bytes.
Module 6c5e1000: Size: 0x0 (0) bytes.
Total size: Size: 0x0 (0) bytes.
--------------------------------------
Module Lookup Table heaps:
Module 6d311000: Size: 0x0 (0) bytes.
Module 035c4014: Size: 0x0 (0) bytes.
Module 51621000: Size: 0x0 (0) bytes.
Module 6c5e1000: Size: 0x0 (0) bytes.
Total size: Size: 0x0 (0) bytes.
--------------------------------------
Total LoaderHeap size: Size: 0x19000 (102400) bytes.
=======================================
loader heap is 102400 bytes which seem normal. Next, let's look at the managed heap.
0:000> !eeheap -gc
Number of GC Heaps: 1
generation 0 starts at 0x14921a90
generation 1 starts at 0x148ced8c
generation 2 starts at 0x053c1000
ephemeral segment allocation context: none
segment begin allocated size
053c0000 053c1000 063bf260 0xffe260(16769632)
08cf0000 08cf1000 09cee9a4 0xffd9a4(16767396)
0af10000 0af11000 0bf0e554 0xffd554(16766292)
0d180000 0d181000 0e17ea30 0xffda30(16767536)
0f150000 0f151000 1014e680 0xffd680(16766592)
10680000 10681000 1167f32c 0xffe32c(16769836)
12650000 12651000 13306a20 0xcb5a20(13326880)
14620000 14621000 14922ff4 0x301ff4(3153908)
Large object heap starts at 0x063c1000
segment begin allocated size
063c0000 063c1000 063c5508 0x4508(17672)
Total Size: Size: 0x6fae450 (117105744) bytes.
------------------------------
GC Heap Size: Size: 0x6fae450 (117105744) bytes.
The total size of managed heap size is around 117MB which is suspicious, considering the application is about to exit and it forced garbage collection earlier, we need to take a second look.
0:000> !DumpHeap -stat
Statistics:
MT Count TotalSize Class Name
...
035c4f3c 1 12 Finalizer.Worker
035c4d68 1 12 Finalizer.Program
6d82ffe4 10 17848 System.Object[]
51645130 10000 120000 System.Management.IWbemClassObjectFreeThreaded
6d82ce08 10000 160000 System.__ComObject
035c4e1c 10000 160000 Finalizer.Wmi
6d823bfc 10001 240024 System.Collections.ArrayList
51644f4c 10000 280000 System.Management.ManagementScope
516433c4 20001 320016 System.Management.WbemDefPath
516413f0 20001 400020 System.Management.ManagementPath
51642bfc 10000 480000 System.Management.ManagementNamedValueCollection
6d832ae8 10015 480816 System.Collections.Hashtable+bucket[]
6d8329f8 10015 520780 System.Collections.Hashtable
5164401c 10000 560000 System.Management.ConnectionOptions
516445dc 10000 640000 System.Management.ManagementClass
51640e94 60000 1920000 System.Management.IdentifierChangedEventHandler
035e1e98 39228 10578600 Free
6d83419c 10001 100120269 System.Byte[]
Total 249927 objects
We can see that we still have 10000 instances of the Wmi and 10001 instances of Byte[].
0:000> !DumpHeap -type Finalizer.Wmi
Address MT Size
053c5c10 035c4e1c 16
053cc57c 035c4e1c 16
148e5344 035c4e1c 16
148e883c 035c4e1c 16
148ebd34 035c4e1c 16
...
1491a2c4 035c4e1c 16
1491d7bc 035c4e1c 16
14920cb4 035c4e1c 16
Statistics:
MT Count TotalSize Class Name
035c4e1c 10000 160000 Finalizer.Wmi
Total 10000 objects
and then, let's find a specific object's root.
0:000> !gcroot 14920cb4
Note: Roots found on stacks may be false positives. Run "!help gcroot" for
more info.
Scan Thread 0 OSTHread 299c
Scan Thread 2 OSTHread 27d4
Finalizer queue:Root:14920cb4(Finalizer.Wmi)
So the object was held by f-reachable queue with details like below:
0:000> !finalizequeue
SyncBlocks to be cleaned up: 0
Free-Threaded Interfaces to be released: 0
MTA Interfaces to be released: 0
STA Interfaces to be released: 0
----------------------------------
generation 0 has 3 finalizable objects (124e4050->124e405c)
generation 1 has 3 finalizable objects (124e4044->124e4050)
generation 2 has 13 finalizable objects (124e4010->124e4044)
Ready for finalization 29998 objects (124e405c->12501514)
Statistics for all finalizable objects (including all objects ready for finalization):
MT Count TotalSize Class Name
6d8342f4 1 20 Microsoft.Win32.SafeHandles.SafePEFileHandle
6d832970 1 20 Microsoft.Win32.SafeHandles.SafeFileHandle
6d8247a0 1 20 Microsoft.Win32.SafeHandles.SafeWaitHandle
6d7ef8f8 1 20 Microsoft.Win32.SafeHandles.SafeFileMappingHandle
6d7ef8a8 1 20 Microsoft.Win32.SafeHandles.SafeViewOfFileHandle
6d8307e4 1 52 System.Threading.Thread
6d814f18 1 60 System.Runtime.Remoting.Contexts.Context
6d8323dc 2 88 System.Threading.ReaderWriterLock
6d82df74 8 160 Microsoft.Win32.SafeHandles.SafeRegistryHandle
51645130 10000 120000 System.Management.IWbemClassObjectFreeThreaded
035c4e1c 10000 160000 Finalizer.Wmi
516445dc 10000 640000 System.Management.ManagementClass
Total 30017 objects
why those 29998 objects haven’t been finalized? Let's check the finalizer thread:
0:000> !threads
ThreadCount: 2
UnstartedThread: 0
BackgroundThread: 1
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
Lock
ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
0 1 299c 035f83a0 2a020 Preemptive 149224A8:00000000 035f2320 1 MTA
2 2 27d4 03607bd8 2b220 Preemptive 00000000:00000000 035f2320 0 MTA (Finalizer)
0:000> ~2s
eax=00000000 ebx=074bf5cc ecx=00000000 edx=00000000 esi=00000000 edi=074bf5b8
eip=7760048c esp=074bf574 ebp=074bf590 iopl=0 nv up ei pl nz na pe nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000206
ntdll!NtWaitForAlertByThreadId+0xc:
7760048c c20800 ret 8
0:002> k
# ChildEBP RetAddr
00 074bf570 775bd1d9 ntdll!NtWaitForAlertByThreadId+0xc
01 074bf590 775bd11d ntdll!RtlpWaitOnAddressWithTimeout+0x33
02 074bf5d4 775bd016 ntdll!RtlpWaitOnAddress+0xa5
03 074bf610 775da38a ntdll!RtlpWaitOnCriticalSection+0xab
04 074bf630 775da259 ntdll!RtlpEnterCriticalSectionContended+0x12a
*** WARNING: Unable to verify checksum for native.dll
05 074bf638 5ce21564 ntdll!RtlEnterCriticalSection+0x49
06 074bf710 03990757 native!UnInit+0x34
[c:\from mac\download\adndsrc\chapter5\native\05native\05native.cpp @ 45]
WARNING: Frame IP not in any known module. Following frames may be wrong.
07 074bf750 039908ec 0x3990757
08 074bf770 6e94b9c2 0x39908ec
09 074bf7c4 6e94bab5 clr!FastCallFinalize+0x6d
0a 074bf7e8 6e94b83c clr!MethodTable::CallFinalizer+0x139
0b 074bf7f8 6e94b8b3 clr!CallFinalizer+0xa6
0c 074bf848 6e94b915 clr!FinalizerThread::DoOneFinalization+0x84
0d 074bf87c 6e94ad11 clr!FinalizerThread::FinalizeAllObjects+0xa6
0e 074bf8ac 6e86d03a clr!FinalizerThread::FinalizerThreadWorker+0xed
0f 074bf8c0 6e86d0a4 clr!ManagedThreadBase_DispatchInner+0x71
10 074bf964 6e86d171 clr!ManagedThreadBase_DispatchMiddle+0x7e
11 074bf9c0 6e8f1ad8 clr!ManagedThreadBase_DispatchOuter+0x5b
12 074bf9e8 6e8f1b9f clr!ManagedThreadBase::FinalizerBase+0x33
13 074bfa24 6e7cedf1 clr!FinalizerThread::FinalizerThreadStart+0xd4
14 074bfac8 74c28654 clr!Thread::intermediateThreadProc+0x55
15 074bfadc 775f4b17 kernel32!BaseThreadInitThunk+0x24
16 074bfb24 775f4ae7 ntdll!__RtlUserThreadStart+0x2f
17 074bfb34 00000000 ntdll!_RtlUserThreadStart+0x1b
So at this point, it can be concluded that the finalize method is blocked!
0:002> !clrstack
OS Thread Id: 0x27d4 (2)
Child SP IP Call Site
074bf71c 7760048c [InlinedCallFrame: 074bf71c]
074bf718 03990757 DomainBoundILStubClass.IL_STUB_PInvoke()
074bf71c 039908ec [InlinedCallFrame: 074bf71c] Finalizer.Worker.UnInit()
074bf758 039908ec Finalizer.Worker.Finalize()
[C:\Users\mrleo\Documents\Visual Studio 2015\Projects\ConsoleApplication1\Program.cs @ 50]
074bf980 6e94b9c2 [DebuggerU2MCatchHandlerFrame: 074bf980]
In essence, the finalizer thread is executing the Finalize method of our Worker type, which in turn uses the interoperability services to call into a native module (Native), which in turn attempts to enter a critical section, but appears to be getting stuck.
A closer look at the source code shows that the ProcessData function we call from the Initialize method in our Finalizer class enters a critical section but never, subsequently, releases the critical section. The UnInit function in turn attempts to enter the critical section, but because it is already locked, the call waits indefinitely. Because the usage of the Worker class (which also has a Finalize method) precedes the usage of the Wmi class, the Worker class instance ends up on the f-reachable queue before any of our numerous Wmi instances, which also means that the finalizer thread will pick that instance up first and immediately get stuck.
Now, because the finalizer thread simply picks up objects on the f-reachable queue in a serialized fashion, any object that causes the finalizer thread to fail (or get stuck in this case), will prevent the finalizer thread from executing the rest of the Finalize methods on the f-reachable queue causing the objects never to get cleaned up and garbage collected. The net result is that memory consumption will grow in an unbounded fashion and eventually will result in an OutOfMemoryException.
Using a Finalize method can be far from trivial. Great care must be taken to ensure that there are no inadvertent bugs (such as a deadlock) in the Finalize code because even the smallest of bugs can cause not only that specific object not to be cleaned up but also all other objects that follow on the f-reachable queue.
Points of Interest
In this article, we learnt:
- Managed heap concepts and how finalization works
- How to generate process dump file using Windows built-in task manager
- How to analyze the dump file with various commands
- Never do something suspicious or complex in finalizer, this could introduce inadvertent bugs
History
