ICorProfilerCallback2: CLR Profiler does not log all Leave messages
I'm trying to write a profiler that logs all .Net method calls in a process. The goal is to make it highly professional and keep the last 5-10 minutes in memory (fixed buffer, cyclically overwrite old information) until the user triggers that information to write to disk. The intended use is tracking, rarely reproducing performance issues.
I started with the SimpleCLRProfiler project from https://github.com/appneta/SimpleCLRProfiler . The profiler uses the ICorProfilerCallback2 callback interface for .Net profiling. I got it to compile and work in my environment (Win 8.1, .Net 4.5, VS2012). However, I have noticed that sometimes Remaining calls for which incoming calls have been registered are being missed. An example of calling Console.WriteLine (I reduced the DbgView output to the minimum necessary for understanding):
Line 1481: Entering System.Console.WriteLine
Line 1483: Entering SyncTextWriter.WriteLine
Line 1485: Entering System.IO.TextWriter.WriteLine
Line 1537: Leaving SyncTextWriter.WriteLine
Two incoming calls have no corresponding outputs. Net profiled code looks like this:
Console.WriteLine("Hello, Simple Profiler!");
The corresponding 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 anyone have an idea why the .Net Profiler will not fulfill checkout requests for all checkout methods? BTW, I have checked that OnLeaveMethod does not unexpectedly exit any trace due to an exception or so. This is not true.
Thanks Christophe
source to share
Since it seems like stakx doesn't go back to my question to give an official answer (and get credit), so I'll do it for him: as stakx hinted, I didn't log tail calls. In fact, I didn't even know about this concept, so I completely ignored this connection method (it was connected but empty). I found a good explanation of tail calls here: David Broman CLR Profiling API Blog: Enter, Leave, Tailcall Hooks Part 2: Tall stories about tail calls .
I am quoting from the link above:
The tail call is a compiler optimization that preserves instruction execution and preserves read and write operations from 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 rather than a normal call.
Consider this code:
static public void Main() {
Helper();
}
static public void Helper() {
One();
Three();
}
static public void Three() {
...
}
When the Three method is called without optimizing the tail call, the stack will look like this.
Three
Helper
Main
When optimizing the tail call, the stack looks like this:
Three
Main
Therefore, before calling Three, due to optimization, the Helper method has already been popped from the stack, and, as a result, there is one less method on the stack (less memory usage), and some executions and writes to memory were saved.
source to share