Getting Started with .NET Framework Profiling
by March 27, 2014

Filed under: Performance Monitoring

AppNeta no longer blogs on DevOps topics like this one.

Feel free to enjoy it, and check out what we can do for monitoring end user experience of the apps you use to drive your business at www.appneta.com.

Usually when developers talk about profiling, they mean running code they wrote in some sort of development environment to get better understanding of its performance. That’s the valid use case, but what happens when code is released in the wild? Your customers will run it in configurations you wouldn’t imagine, the data can be differently encoded and if you code behaves unexpectedly it’s very difficult to figure out what is wrong.

What makes things worse is that most of the time it’s impossible to deploy your development environment on customer’s machine so you can debug it there and figure out problem areas. If you are developing in .NET then you have an option to get better insight into you application behavior.

.NET provides a profiling interface that you can implement. Upon registering a profiler with the CLR, it will instantiate your object and pass you notifications when specific events happen during execution. Moreover, the CLR will let you inspect or even modify code before it is JIT compiled. In this article, we’ll look at exactly what is possible with this technique, and, in particular, how to write your own profiler.

I put together a simple profiler project that will help you getting started. It’s available at on Github. Let’s look at the code.

The SimpleProfiler class implements ICorProfilerCallback3 interface, the core profiling interface available in the CLR. We’re going to implement a simple logging profiler. A more complicated example could try to access or modify code, which is possible, but we’ll focus on getting something as simple as possible working.

Let’s look at the CSimpleProfiler implementation. Once we get past the usual stuff for creation and destruction, the Initialize() and Shutdown() methods are the main configuration methods. Here is where we let the CLR know what kind of notifications we want to receive.

STDMETHODIMP CSimpleProfiler::Initialize(IUnknown* ICorProfilerInfoUnknown)
{
   Trace_f(L"CSimpleProfiler::Initialize()\n");
   // Exclude runtime libraries that we don't want to trace… see Github for the full version.
   return monitorEnterLeave(ICorProfilerInfoUnknown);
}
STDMETHODIMP CSimpleProfiler::Shutdown()
{
   Trace_f(L"CSimpleProfiler::Shutdown()\n");
   return S_OK;
}
HRESULT CSimpleProfiler::monitorEnterLeave(IUnknown* ICorProfilerInfoUnknown)
{
   HRESULT hr = E_FAIL;
   if (ICorProfilerInfoUnknown != NULL)
   {
      hr = ICorProfilerInfoUnknown->QueryInterface(__uuidof(ICorProfilerInfo3), reinterpret_cast<void**>(&profilerInfo3));
      if (SUCCEEDED(hr))
      {
         hr = profilerInfo3->SetEventMask((DWORD)(COR_PRF_MONITOR_ENTERLEAVE | COR_PRF_ENABLE_FRAME_INFO | COR_PRF_ENABLE_FUNCTION_ARGS));
         if (SUCCEEDED(hr))
            hr = registerGlobalCallbacks();
         else
            Trace_f(L"Failed to set event mask: COR_PRF_MONITOR_ENTERLEAVE | COR_PRF_ENABLE_FRAME_INFO | COR_PRF_ENABLE_FUNCTION_ARGS");
      }
   }
   return hr;
}

In the Initialize() method, we call monitorEnterLeave() where we set COR_RPF_MONITOR_ENTERLEAVE, a mask that lets CLR know what we want. (The other two flags, if set, will let you inspect the call stack and arguments, but we’re only interested in timings).  Then we register a callback, which the CLR will call when managed code methods are executed (entered or left). On Shutdown(), we do nothing: since we attached the profiler on startup, it’ll die at the same time the process ends. There’s an option to attach the profiler dynamically, but it’s available only for CLR 4.0 and up.

Now that we have registered our callback methods, we’re pretty much good to go. A note about callbacks implementation: you will see a bit of assembly there. The reason for that is to restore the call stack to it’s original state after our callbacks were called. We are in guts of CLR and should be extra careful. The documentation for callbacks explicitly says that we should clean up after ourselves. For x64 targets we cannot use inline assembly within .cpp file, so we use a separate .asm file and enable assembly compilation in VisualStudio so it will be build.

At this point, we are done with the bulk of the code, so let’s test it out. The solution includes an AppStarter project that allows us to pick an application to profile and perform all required configuration so CLR knows what profiler to load and where to find it.

In order to successfully run, we need to have 3 things:

  • We have to set COR_ENABLE_PROFILING to “1”, to indicate that we want to profile.
  • We have to set COR_PROFILER_PATH, which points to the profiler DLL.
  • We have to set COR_PROFILER to the GUID of the profiler class.

If all three of these are true, the CLR knows that we want to profile this application, has information where to find dll, and knows how to create an instance of the profiler. It will try to do that and, if successful, we should see traces in DebugView.

DebugView is an utility that let us to see output from the profiler. You can download it here from TechNet. If you don’t see traces go to Capture menu and try to check all the options.

The project also has a simple application that we can try to profile. Once DebugView is running, start AppStarter.exe and choose TestApp.exe as a profiler target. When you click Start, you should see traces from CSimpleProfiler constructor and Initialize() methods. The TestApp is waiting for the user input. If you want to see what’s going on inside profiler, just attach your debugger to the TestApp.exe process. In “Attach To” field you should have “Native code” in this case you should be able to debug native code from you managed application.

If you put breakpoints on OnEnterWithInfo() and OnLeaveWithInfo(), you can even see how the CLR is calling your profiler.

void CSimpleProfiler::OnEnterWithInfo(FunctionID functionId, COR_PRF_ELT_INFO eltInfo)
{
   MethodInfo info;
   HRESULT hr = info.Create(profilerInfo3, functionId);
   if (FAILED(hr))
      Trace_f(L"Enter() failed to create MethodInfo object (%s)", _com_error(hr).ErrorMessage());
   if (!tracingEnabledForScope(info.className, info.methodName))
      return; // Skip classes we are not interested in.
   Trace_f(L"[%d] Entering %s.%s", info.threadId, info.className.c_str(), info.methodName.c_str());
}
void CSimpleProfiler::OnLeaveWithInfo(FunctionID functionId, COR_PRF_ELT_INFO eltInfo)
{
   MethodInfo info;
   HRESULT hr = info.Create(profilerInfo3, functionId);
   if (FAILED(hr))
      Trace_f(L"Enter() failed to create MethodInfo object (%s)", _com_error(hr).ErrorMessage());
   if (!tracingEnabledForScope(info.className, info.methodName))
      return;
   Trace_f(L"[%d] Leaving %s.%s", info.threadId, info.className.c_str(), info.methodName.c_str());
}

There are a few helper classes/methods show how to get information about what method is currently executing. And if you don’t want your profiler to be noisy, you can exclude certain methods adding them to the list of excluded scopes.

If you download the code, you can start playing with CLR profiler API in a matter of minutes. There are lots of areas to experiment. You can put a timer in enter/leave methods to measure how much time it took to execute. Even simpler, just a fact that particular method was called is quite valuable. You can just log all method calls from your testing framework and then using reflection compare all methods against methods that were called to figure out your testing coverage. That’s just a few ideas; I am sure you’ll come up with more on your own.

Happy hacking!

Monitor .NET in production like you've never seen it before

Create your free account of TraceView and AppView today! Create your free account
  • mjhillman

    If you are using Visual Studio 2010 what would the profile dll path and GUID be?