ICorProfilerCallback2: CLR profiler does not log all Leave calls

Question

I am trying to write a profiler that logs all .Net method calls in a process. The goal is to make it highly performant and keep let's say the last 5-10 minutes in memory (fixed buffer, cyclically overwrite old info) until the user triggers that info to be written to disk. Intended use is to track down rarely reproducing performance issues.

I started off with the SimpleCLRProfiler project from https://github.com/appneta/SimpleCLRProfiler. The profiler makes use of the ICorProfilerCallback2 callback interface of .Net profiling. I got it to compile and work in my environment (Win 8.1, .Net 4.5, VS2012). However, I noticed that sometimes Leave calls are missing for which Enter calls were logged. Example of a Console.WriteLine call (I reduced the output of DbgView to what is minimally necessary to understand):

Line 1481: Entering System.Console.WriteLine
Line 1483: Entering SyncTextWriter.WriteLine
Line 1485: Entering System.IO.TextWriter.WriteLine
Line 1537: Leaving SyncTextWriter.WriteLine

Two Entering calls don't have corresponding Leaving calls. The profiled .Net code looks like this:

Console.WriteLine("Hello, Simple Profiler!");

The relevant SimpleCLRProfiler methods are:

HRESULT CSimpleProfiler::registerGlobalCallbacks() 
{
   HRESULT hr = profilerInfo3->SetEnterLeaveFunctionHooks3WithInfo(
      (FunctionEnter3WithInfo*)MethodEntered3, 
      (FunctionEnter3WithInfo*)MethodLeft3, 
      (FunctionEnter3WithInfo*)MethodTailcall3);

   if (FAILED(hr))
      Trace_f(L"Failed to register global callbacks (%s)", _com_error(hr).ErrorMessage());

   return S_OK;
}

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());

   Trace_f(L"[%p] [%d] Entering %s.%s", functionId, GetCurrentThreadId(), 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());

   Trace_f(L"[%p] [%d] Leaving %s.%s", functionId, GetCurrentThreadId(), info.className.c_str(), info.methodName.c_str());
}

Does anybody have an idea, why the .Net Profiler would not perform Leave calls for all leaving methods? By the way, I checked that the OnLeaveMethod does not unexpectedly exit before any trace due to an exception or so. It doesn't.

Thanks, Christoph

Well, there's a pattern, the methods that are missing are normally inlined so can't generate a Leave. SyncTextWriter.WriteLine() is not, it has a [MethodImpl]. It is not entirely clear to me why you can see the Enter, you probably should also watch ICorProfilerCallback::JITInlining(). — Hans Passant, Jun 20 '15 at 08:25
Stakx, you got it! I didn't log tail calls. In fact, I wasn't even aware of the concept so I had completely ignored that hook method. I found a good explanation here: http://blogs.msdn.com/b/davbr/archive/2007/06/20/enter-leave-tailcall-hooks-part-2-tall-tales-of-tail-calls.aspx. I suggest that you create an official answer for this issue and I'll mark it as such. Thanks! — Christoph, Jun 21 '15 at 18:20

score 4 · Accepted Answer · edited Jan 21 '19 at 07:24

Since stakx does not seem to be coming back to my question to provide an official answer (and get the credit) so I will do it for him: As stakx had hinted at, I didn't log tail calls. In fact, I wasn't even aware of the concept so I had completely ignored that hook method (it was wired up but empty). I found a good explanation of tail calls here: David Broman's CLR Profiling API Blog: Enter, Leave, Tailcall Hooks Part 2: Tall tales of tail calls.

I quote from the link above:

Tail calling is a compiler optimization that saves execution of instructions and saves reads and writes of stack memory. When the last thing a function does is call another function (and other conditions are favorable), the compiler may consider implementing that call as a tail call, instead of a regular call.

Consider this code:

static public void Main() {
    Helper();
}

static public void Helper() {
    One();
    Three();
}

static public void Three() {
    ...
}

When method Three is called, without tail call optimization, the stack will look like this.

Three
Helper
Main

With tail call optimization, the stack looks like this:

Three
Main

So before calling Three, due to the optimization, method Helper was already popped of the stack and as a result, there is one less method on the stack (less memory usage) and also some executions and memory write operations were saved.

ICorProfilerCallback2: CLR profiler does not log all Leave calls

1 Answers1