Wednesday, December 7, 2011

Managed Console Handle Leak

We were seeing a minor handle leak in our console the other day, so let’s turn on the Performance Monitor, set it up to watch handle usage and point it at the console process.  Here’s what we see:

image

This is not good, but it exhibits a pattern that should be familiar to C# developers.  It’s not a true “leak” in that the handle count goes down after a short amount of time.  So what’s going on? 

The first thing that comes to mind is that we’re regularly allocating SafeHandles either directly (that would be weird) or indirectly (much more likely) through a helper class like a FileStream or a xResetEvent.  That would explain why the handle count is steadily going up for the lifetime of the application.  The periodic drops can be explained by the garbage collector.  Whenever it performs a collection the GC is sweeping up a bunch of unreachable SafeHandles and running their finalizers which release a bunch of kernel handles at once.  The frequency and regularity of the drops leads us to believe the objects being swept up are in Generation 0 which is collected at the highest rate.

Now that we’ve got an idea of what to look for we can run the process in a profiler and try to identify who is allocating all these handles.  SciTech’s .NET Memory Profiler is very good at diagnosing handle leaks (we’ve had a few!) so let’s start it up and tell it to profile an application.

 

image

We’ll start up the wizard by clicking on “Profile Application”.

image

We’ll go through the wizard, selecting all the defaults until reaching the “unmanaged resource tracker” page.  Enabling this because will allow us to determine if we’ve got native code leaking handles. Our console is a mixed-mode process so it can help point us towards the culprit if it’s not in managed code.

image

So here’s the settings at the end of the wizard.  We’ll click start and begin profiling.

image

 

By-and-large we’re not interested in the vagaries of process bootstrapping so we’ll wait until the console process is “stable” before taking our first snapshot.

It’s worth pointing out that resource usage is a little higher than usual while the process is run inside of the profiler.  Don’t panic!  While the absolute numbers are a little higher the pattern we’re investigating remains.

When investigating out-of-control handle usage we can leverage some knowledge of how the .NET BCL is designed to quickly find them.  All kernel handles in .NET are wrapped in SafeHandles, which have finalizers to protect them from leaking system resources in case a developer forgets to dispose of them.  They’re all defined in the Microsoft.Win32.SafeHandles namespace, so we can use a simple filter: *SafeHandle, to show all the live SafeHandle objects in the system:

image

 

The results are surprising: the total number of live SafeHandle objects is 32?  Looking at the process’ handle count we see numbers over 1000, so obviously these objects do not account for all the handles.  Let’s look at the unmanaged resources to see if we can find the rest of the process’ handles.  To do so we simply remove the namespace filter and enter a Name/Resource filter.  That unmanaged resource tracker we turned on earlier will name all the handles in the process with the suffix (HANDLE), so our filter will be *(HANDLE).  These are the results:

image

Again the numbers don’t add up.  There seems to be an awful lot of event handles, but not nearly enough to account for all of them.  Let’s take another snapshot and see what shows up.  We’ll apply our *SafeHandle filter and look at how many new handles were allocated between the two snapshots:

image

Now there’s only 9 SafeHandles?  So we lost three between snapshots!  This does not track with what we’re seeing in the performance monitor.  Let’s check the unmanaged resources:

image

This, too, has not changed from the previous snapshot.  How, then, do we explain the steady uptick and then drop in the handle count if the count is steady between snapshots?  The profiler doesn’t tell us enough, but we’ll find the answer in part 2!

No comments:

Post a Comment