How performant is StackFrame?

Question

I am considering using something like StackFrame stackFrame = new StackFrame(1) to log the executing method, but I don't know about its performance implications. Is the stack trace something that is build anyway with each method call so performance should not be a concern or is it something that is only build when asked for it? Do you recommend against it in an application where performance is very important? If so, does that mean I should disable it for the release?

Answer 1

From the MSDN documentation, it seems like StackFrames are being created all the time:

A StackFrame is created and pushed on the call stack for every function call made during the execution of a thread. The stack frame always includes MethodBase information, and optionally includes file name, line number, and column number information.

The constructor new StackFrame(1) you'd call would do this:

private void BuildStackFrame(int skipFrames, bool fNeedFileInfo)
{
    StackFrameHelper sfh = new StackFrameHelper(fNeedFileInfo, null);
    StackTrace.GetStackFramesInternal(sfh, 0, null);
    int numberOfFrames = sfh.GetNumberOfFrames();
    skipFrames += StackTrace.CalculateFramesToSkip(sfh, numberOfFrames);
    if ((numberOfFrames - skipFrames) > 0)
    {
        this.method = sfh.GetMethodBase(skipFrames);
        this.offset = sfh.GetOffset(skipFrames);
        this.ILOffset = sfh.GetILOffset(skipFrames);
        if (fNeedFileInfo)
        {
            this.strFileName = sfh.GetFilename(skipFrames);
            this.iLineNumber = sfh.GetLineNumber(skipFrames);
            this.iColumnNumber = sfh.GetColumnNumber(skipFrames);
        }
    }
}

GetStackFramesInternal is an external method. CalculateFramesToSkip has a loop that operates exactly once, since you specified only 1 frame. Everything else looks pretty quick.

Have you tried measuring how long it would take to create, say, 1 million of them?

Answer 2

A quick and naive test indicates that for performance-sensitive code, yes, you want to pay attention to this:

Don't generate 100K frames: 3ms

Generate 100K frames: 1805ms

About 20 microseconds per generated frame, on my machine. Not a lot, but a measurable difference over a large number of iterations.

Speaking to your later questions ("Should I disable StackFrame generation in my application?"), I'd suggest you analyze your application, do performance tests like the one I've done here, and see if the performance difference amounts to anything with your workload.

using System;
using System.Diagnostics;

namespace ConsoleApplication
{
    class Program
    {
     static bool generateFrame;

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

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

      // call 100K times; no stackframes
      sw = Stopwatch.StartNew();
      for (int i = 0; i < 100000; i++)
      {
       CallA();
      }
      sw.Stop();
      Console.WriteLine("Don't generate 100K frames: {0}ms"
                                 , sw.ElapsedMilliseconds);

      // call 100K times; generate stackframes
      generateFrame = true;
      sw = Stopwatch.StartNew();
      for (int i = 0; i < 100000; i++)
      {
       CallA();
      }
      Console.WriteLine("Generate 100K frames: {0}ms"
                           , sw.ElapsedMilliseconds);

      Console.ReadKey();
     }

     private static void CallA()
     {
      CallB();
     }

     private static void CallB()
     {
      CallC();
     }

     private static void CallC()
     {
      if (generateFrame)
      {
       StackFrame stackFrame = new StackFrame(1);
      }
     }
    }
}

Answer 3

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

Answer 4

I am considering using something like StackFrame stackFrame = new StackFrame(1) to log the executing method

Out of interest: Why? If you only want the current method, then

string methodName = System.Reflection.MethodBase.GetCurrentMethod().Name;

seems better. Maybe not more performant (I didn't compare, but Reflection shows that GetCurrentMethod() does not simply create a StackFrame but does some "magic"), but clearer in it's intent.