A picture is worth 1000 words

Two to three weeks ago if you ran this battery of garbage collection related tests in moonlight, they'd mostly be red. How things have changed :)

Writing a profiler for mono

As some of you may know, my day job is working on Moonlight, the FOSS implementation of Silverlight. This is a fairly complex piece of code as we have C++ interoperating with C# and Javascript, so managing the lifecycle of objects can be difficult. C++ refcounts, C# has an automatic garbage collector and Javascript... well, let's just say that it complicates things a *lot* when combined with the other two languages.

One of the tricks we use to ensure that objects do not die early is to use a (normal) GCHandle on our C# objects to ensure the garbage collector doesn't mark them as junk before they're definitely finished with in C++. However, we were having issues where some of our objects appeared to never ever get garbage collected even though they should be eligible. We suspected that excess GCHandles were causing it but we had no easy way of tracking this. Without detailed information on when and where the GCHandles were allocated, it would be next to impossible to track down where we were going wrong. After several aborted attempts to track this with Console.WriteLine I figured there must be a better way.

How about a custom profiler for mono?

Documentation on this is fairly sparse currently, so hopefully this will help. Thanks go to Paolo Molaro for helping me when I got stuck! This code is mostly copied/pasted from moonlight so it's C++ ish and also may contain some moonlight specific code.

Step 1:
Open up the "mono/metadata/profiler.h" file and check out all the profiler hooks that are available. They are all documented in profiler.c, so open that if you want a description of how they all work. Take note of the ones you'll need. All I needed to do was track GCHandle allocations, so I just wanted this hook:

void mono_profiler_install_gc_roots    (MonoProfileGCHandleFunc handle_callback, MonoProfileGCRootFunc roots_callback);

Step 2:
I now know what function I need to provide and the data I want to gather, so it's time to create a struct to store my data. This is an opaque struct which will be passed to the mono runtime and passed back in every profiler hook, so you can stick whatever you want in it. I know I want to store stacktraces, allocated gchandles and a typename, so I'll start with just those. I'll also declare my prototype for my profiler hook here.

struct _MonoProfiler {
const char *type_name;
GPtrArray *gchandles;
GPtrArray *stacktraces;
Moonlight::Mutex locker; /* used to ensure only one thread accesses the arrays */

static void track_gchandle (_MonoProfiler *prof, int op, int type, uintptr_t handle, MonoObject *obj);
};

typedef _MonoProfiler MonoProfiler;

Step 3:
Implementation time! First the constructor for the MonoProfiler. I use an environment variable to limit which types we store stacktraces for as they're expensive to generate and consume a lot of memory to store when you have 10,000s of them. The important functions are the last three. The first registers our profiler with the runtime. The second installs the hook so we can get notifications for gchandle allocations. The final call enables the gc_handle events in the profiler which makes the runtime invoke the hook we just registered.

_MonoProfiler::_MonoProfiler ()
{
   type_name = g_getenv ("GCHANDLES_FOR_TYPE");

   gchandles = g_ptr_array_new ();
   stacktraces = g_ptr_array_new_with_free_func (g_free);
   /* Register the profiler with mono */
   mono_profiler_install (this, NULL);
   /* Supply a function for the gc_roots hook */
   mono_profiler_install_gc_roots (track_gchandle, NULL);
   /* Enable gc_roots tracking in the profiler so our hook is invoked */
   mono_profiler_set_events (MONO_PROFILE_GC_ROOTS);
}

Now all I need is the implementation for track_gchandle and I'm done!

void
MonoProfiler::track_gchandle (MonoProfiler *prof, int op, int type, uintptr_t handle, MonoObject *obj)
{
   // Ignore anything that isn't a strong GC handle (docs say type == 2 is a strong gchandle)
   if (type != 2)
       return;

   prof->locker.Lock ();

   GPtrArray *gchandles = prof->gchandles;
   GPtrArray *stacktraces = prof->stacktraces;

   if (op == MONO_PROFILER_GC_HANDLE_CREATED) {
       // Add the GCHandle to this array
       g_ptr_array_add (gchandles, (gpointer) handle);
       // If the target of the gchandle is of the correct type, store its stack trace
       // Otherwise store NULL so that we can keep the index of the gchandle and corresponding
       // stack trace in sync.
       if (prof->type_name && !strcmp (prof->type_name, mono_class_get_name (mono_object_get_class(obj))))
           g_ptr_array_add (stacktraces, get_stack_trace ());
       else
           g_ptr_array_add (stacktraces, NULL);
   } else if (op == MONO_PROFILER_GC_HANDLE_DESTROYED) {
       // Walk our list of gchandles and when we find the index of the destroyed handle
       // remove the handle and corresponding stacktrace
       for (int i = 0; i < (int)gchandles->len; i++) {
           if (g_ptr_array_index (gchandles, i) == (gpointer) handle) {
               g_ptr_array_remove_index_fast (gchandles, i);
               g_ptr_array_remove_index_fast (stacktraces, i);
               break;
           }
       }
   }

   prof->locker.Unlock ();
}

Step 4:
Profit! When you're ready, you can iterate over the gchandle array and pull out whatever statistics you want. For example here is the code I use to iterate the gchandles array and work out how many instances of each object type there are.

void
accumulate_g_ptr_array_by_type (gpointer data, gpointer user_data)
{
   // The hashtable I passed in as the user_data in g_ptr_array_foreach
   // which i am using to link a type name to a count
   GHashTable *by_type = (GHashTable*) user_data;

   // Get the MonoObject from the gchandle.
   MonoObject *ob = mono_gchandle_get_target (GPOINTER_TO_INT (data));

   // Get the type name from the mono_object
   const char *name = mono_class_get_name (mono_object_get_class(ob));

   // Find out how many instances we have already
   int count = GPOINTER_TO_INT (g_hash_table_lookup (by_type, name)) + 1;

   // Update the hashtable with an incremented count.
   g_hash_table_insert (by_type, name, GINT_TO_POINTER (count));
}

I run that hashtable through another function to order to sort the list by the number of each type of object allocated so I can have a nicely formatted list as follows:

1 instances GCHandled of type Surface
1 instances GCHandled of type Deployment
4 instances GCHandled of type NameScope
20 instances GCHandled of type ControlTemplate
218 instances GCHandled of type MonoType
3985 instances GCHandled of type Uri

Needless to say, it's now immediately obvious to me that Uris are being GChandled and never freed, so i just have to enable tracing of their stacktraces and I can see exactly where we allocated the handle and from there figure out why we haven't freed it.