Some Twists on Blocked Finalizers
April 3rd, 2006
Our problem was manifesting itself in a very long-running console application that both connected to a database and made web service calls. Eventually the app would start hitting
OutOfMemoryExceptions. (Completely unrelated to these
OutOfMemoryExceptions. We have a high incidence of
OutOfMemoryExceptions around here.)
Fixing the Wrong Problem and Moving the Goalposts
My initial reaction to this problem was (sensibly, I think) to attempt to reduce the amount of memory that the application was using. I admit that I was also focused on different problems at the time, so any makeshift solution I could get to work here would have been just fine with me.
We threw in some buffer pools, et cetera, and managed to get the app running slightly longer, but the OOM's always resurfaced. Every time they did, the heap looked completely different due to the semi-drastic changes we were making to the app's memory profile. After the third or maybe fourth change it dawned on me that perhaps we were just confusing the real issue.
The Proverbial Lightbulb Over the Head
The turning point came when I noticed that most of the overly-abundant objects on the heap in a particular dump were types that were likely to be associated with finalizers.
0:000> !dumpheap -stat ------------------------------ ... 2,431,972 48,639,440 System.Threading.WaitHandle/__WaitHandleHandleProtector ...
This hadn't been the case in the previous dumps. Those were eaten alive by byte arrays and strings. By this point, we had done such a fantastic job of optimizing the application for memory usage that the problem came more clearly into focus.
The Road to Victory
At this point I used
!threads in SOS to locate the finalizer thread (some useless info trimmed out here):
0:000> !threads ID APT Exception 0 STA System.OutOfMemoryException 4 MTA (Finalizer)
Thread 4 was stuck in a WaitForSingleObject and, not unrelated to the problem here, the native stacks of almost all of the other threads in the process were in some variation of "WaitUntilGCComplete." Probably should have noticed that sooner. So sue me.
Anyway, the top of the finalizer's stack was interesting:
0:004> ~4k ChildEBP RetAddr 00f0f658 7c822124 ntdll!KiFastSystemCallRet 00f0f65c 77e6baa8 ntdll!NtWaitForSingleObject+0xc 00f0f6cc 77e6ba12 kernel32!WaitForSingleObjectEx+0xac 00f0f6e0 776c54ef kernel32!WaitForSingleObject+0x12 00f0f6fc 77789905 ole32!GetToSTA+0x6f 00f0f71c 77787ed7 ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0xcb
The finalizer is waiting to make a call over to an STA thread. Why's it doing that? And wait, what STA thread? Funny you should ask.
Visual Basic Complications
No technical problem at my post-VBScript company would be complete without Visual Basic putting a unique spin on things. This one is no exception. The authors of this app are fairly oblivious to COM apartments and didn't intentionally create any STA threads. They also weren't using COM Interop directly.
So how did thread zero end up being an STA thread (the astute among you may have noticed this in the !threads output above)? The MSDN documentation seems to clearly say that MTA is the default.
The reason was that the app was written in Visual Basic. If the Main() method in a VB program is lacking the
STAThreadAttribute and the
MTAThreadAttribute, the VB compiler will stick an
STAThreadAttribute on it for you when the MSIL is emitted (the C# compiler doesn't do this). Presumably—and I'm guessing here but I think this is a good guess—this is done for compatibility with VB6.
The main thread of this application was sleeping the vast majority of the time. Admittedly, this is not a fantastic example of multithreaded design, but it wouldn't have caused any problems if the thread were MTA. As Raymond has pointed out, sleeping on an STA thread can have some ill effects.
This problem was solved by decorating the main method with
<MTAThread()>. This is possibly the smallest fix to an apparently massive problem I have ever personally witnessed.
How to Notice This Problem Much Sooner
There are a few ways this could have been less painful. The easiest might have been to check the output of SOS's
!finalizequeue command. If I had done that I would have seen the following (again trimmed for clarity):
Heap 0 generation 0 has 0 finalizable objects generation 1 has 0 finalizable objects generation 2 has 11,212 finalizable objects Ready for finalization 1,163,295 objects
Which does not look healthy. Looking more closely at the native stacks would have also probably yielded a solution on day one.