How performant is StackFrame?

edit: Some background

---

We have a similar feature which is disabled 99% of the time; we were using an approach like:

public void DoSomething()
{
    TraceCall(MethodBase.GetCurrentMethod().Name);
    // Do Something
}

public void TraceCall(string methodName)
{
    if (!loggingEnabled) { return; }
    // Log...
}

TraceCall(MethodBase.GetCurrentMethod().Name)

It was simple, but regardless of whether or not tracing was enabled we were incurring the performance hit of using Reflection to lookup the method name.

Our options were to either require more code in every method (and risk simple mistakes or refusal) or to switch to using StackFrame to determine the calling method only when logging was enabled.

Option A:

public void DoSomething()
{
    if (loggingEnabled)
    {
        TraceCall(MethodBase.GetCurrentMethod().Name);
    }
    // Do Something
}

public void TraceCall(string methodName)
{
    if (!loggingEnabled) { return; }
    // Log...
}

Option B:

public void DoSomething()
{
    TraceCall();
    // Do Something
}

public void TraceCall()
{
    if (!loggingEnabled) { return; }
    StackFrame stackFrame = new StackFrame(1);
    // Log...
}

We opted for Option B. It offers significant performance improvements over Option A when logging is disabled, 99% of the time and is very simple to implement.

Here’s an alteration of Michael’s code, to display the cost / benefit of this approach

using System;
using System.Diagnostics;
using System.Reflection;

namespace ConsoleApplication
{
    class Program
    {
        static bool traceCalls;

        static void Main(string[] args)
        {
            Stopwatch sw;

            // warm up
            for (int i = 0; i < 100000; i++)
            {
                TraceCall();
            }

            // call 100K times, tracing *disabled*, passing method name
            sw = Stopwatch.StartNew();
            traceCalls = false;
            for (int i = 0; i < 100000; i++)
            {
                TraceCall(MethodBase.GetCurrentMethod());
            }
            sw.Stop();
            Console.WriteLine("Tracing Disabled, passing Method Name: {0}ms"
                             , sw.ElapsedMilliseconds);

            // call 100K times, tracing *enabled*, passing method name
            sw = Stopwatch.StartNew();
            traceCalls = true;
            for (int i = 0; i < 100000; i++)
            {
                TraceCall(MethodBase.GetCurrentMethod());
            }
            sw.Stop();
            Console.WriteLine("Tracing Enabled, passing Method Name: {0}ms"
                             , sw.ElapsedMilliseconds);

            // call 100K times, tracing *disabled*, determining method name
            sw = Stopwatch.StartNew();
            traceCalls = false;
            for (int i = 0; i < 100000; i++)
            {
                TraceCall();
            }
            Console.WriteLine("Tracing Disabled, looking up Method Name: {0}ms"
                       , sw.ElapsedMilliseconds);

            // call 100K times, tracing *enabled*, determining method name
            sw = Stopwatch.StartNew();
            traceCalls = true;
            for (int i = 0; i < 100000; i++)
            {
                TraceCall();
            }
            Console.WriteLine("Tracing Enabled, looking up Method Name: {0}ms"
                       , sw.ElapsedMilliseconds);

            Console.ReadKey();
        }

        private static void TraceCall()
        {
            if (traceCalls)
            {
                StackFrame stackFrame = new StackFrame(1);
                TraceCall(stackFrame.GetMethod().Name);
            }
        }

        private static void TraceCall(MethodBase method)
        {
            if (traceCalls)
            {
                TraceCall(method.Name);
            }
        }

        private static void TraceCall(string methodName)
        {
            // Write to log
        }
    }
}

The Results:

Tracing Disabled, passing Method Name: 294ms
Tracing Enabled,  passing Method Name: 298ms
Tracing Disabled, looking up Method Name: 0ms
Tracing Enabled,  looking up Method Name: 1230ms