Debugging Shutdown Finalization Timeout

August 27, 2008

no comments

I’ve written about the perils of non-deterministic finalization before: It is a guaranteed way to get yourself in trouble.

One of the more-or-less known facts is that in the process shutdown scenario, finalizers are called for reachable objects as well.  The total allotted time for this operation is approximately 40 seconds, and each individual finalizer gets approximately 2 seconds to execute.

It is extremely difficult to detect this scenario and debug it because we are talking about the CLR shutdown sequence.

Fortunately, there’s a registry key you can set at HKLM\SOFTWARE\Microsoft\.NETFramework to ensure that when the shutdown finalizer timeout occurs, a debug breakpoint will be raised from the process, allowing you the opportunity to debug it.  Under this key, add a DWORD value called BreakOnFinalizeTimeout and set its value to 1.  (On a 64-bit system, make sure you are using the regedit.exe suitable for the CLR process’ bitness.)

What happens next is that whenever a timeout occurs, you get a breakpoint in the debugger and can see what the finalizer thread is up to.  The breakpoint itself occurs on the shutdown thread inside a function called FinalizerThreadWatchdog.  If you switch to the finalizer thread, you will be able to see the actual code causing the problem:

ntdll!DbgBreakPoint:
00000000`7794fdf0 cc              int     3
0:000> k
<snipped for clarity>
ntdll!DbgBreakPoint
mscorwks!`string’+0x1f52b
mscorwks!WKS::GCHeap::FinalizerThreadWatchDog+0x1e5
mscorwks!EEShutDownHelper+0x309
mscorwks!EEShutDown+0x63
<snipped for clarity>
0:000> !Threads
<snipped for clarity>
   0    1 1870 MTA
   2    2 172c MTA (Finalizer)
0:000> ~2s
ntdll!NtDelayExecution+0xa:
00000000`779505ba c3              ret
0:002> !CLRStack
<snipped for clarity>
FinalizationTimeout.Program.Finalize()
0:002> kb
<snipped for clarity>
ntdll!NtDelayExecution+0xa
KERNEL32!SleepEx+0x84
mscorwks!EESleepEx+0x31
mscorwks!Thread::UserSleep+0x79
mscorwks!ThreadNative::Sleep+0x116
FinalizationTimeout!FinalizationTimeout.Program.Finalize()+0x35 [C:\Users\Sasha\Documents\Visual Studio 2008\Projects\FinalizationTimeout\FinalizationTimeout\Program.cs @ 13]
mscorwks!FastCallFinalizeWorker+0x6
WKS::GCHeap::FinalizerThreadStart+0x133
<snipped for clarity>

So we have code in the Program class calling Thread.Sleep in the finalizer.  That explains it.

By the way, the registry setting obviously affects all .NET applications on the machine.  If you want to isolate the effect to a specific application without affecting the rest, you could use the Application Compatibility Toolkit to enable registry redirection to a special registry location for the specific application.

Add comment
facebook linkedin twitter email

Leave a Reply

Your email address will not be published.

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>

*