Monday, September 24, 2007

The joys of System.Diagnostics.StackFrame

I see code like this an awful lot where a logging function or whatever is passed a string literal of the current method name:
public void TheOldMethodUnderTest()
{
    Log("TheOldMethodUnderTest");
}

private void Log(string methodName)
{
    Console.WriteLine("The name of the method was: {0}", methodName);
}
I've also seen a lot of code like this where the actual method name and the string literal have become out of sync, either because of refactoring, or more commonly, the cut-and-paste method of code reuse. Fortunately there's a really easy way of getting the current stack trace from the System.Diagnostics.StackFrame class. The code below does exactly the same thing as the code above, but the Log() function works out for itself what its caller's name is:
public void TheMethodUnderTest()
{
    Log();
}

private void Log()
{
    System.Diagnostics.StackFrame stackFrame = new System.Diagnostics.StackFrame(1, false);
    System.Reflection.MethodBase method = stackFrame.GetMethod();
    Console.WriteLine("The name of the method was: {0}", method.Name);
}
Doing this kind of thing is a legitimate requirment in many applications, but if you find yourself having to put a lot of boiler-plate code in every method because of cross cutting concerns such as logging, it's worth looking at some kind of AOP framework that provides dynamic proxies that you can intercept.

12 comments:

preet sangha said...
This comment has been removed by the author.
preet sangha said...

hi mike, I've used this approach but move the logging centrally and then walk up the stack 2+ frames (as opposed to your 1) to get the real caller. This way I minimise interuption to the loggee (or should that be logger?). Anyway point taken on logging as a xcutting issue.

Mike Hadlow said...

Hi Preet, how's it going? And when are you going to start blogging?

I don't quite grep what you're saying about moving the logging centrally and walking up the stack 2+ frames. Have you got a simple example?

preet sangha said...

I have I think. I'll clean it up and post.

Richard O'Donnell said...

Though not as flexible, you will find you get much better performance using MethodBase.GetCurrentMethod().Name instead of using the StackFrame object. Here's a test I wrote:


class LogPlay
{
private void Log(string methodName)
{
string x = methodName;
}

public void LogWithMethodBase()
{
Log(MethodBase.GetCurrentMethod().Name);
}

public void LogWithStringValue()
{
Log("LogWithStringValue");
}

public void LogWithStackFrame()
{
Log(new StackFrame().GetMethod().Name);
}

public static void Main()
{
System.Threading.Thread.CurrentThread.Priority = System.Threading.ThreadPriority.Highest;
Stopwatch watch = new Stopwatch();
watch.Start();
LogPlay logger = new LogPlay();
logger.Log("Warm up");

for (int i = 0; i < 100000; i++)
{
logger.LogWithStringValue();
}
watch.Stop();
System.Console.WriteLine("Logging with string value took :{0} seconds", watch.Elapsed.Seconds);
watch.Reset();


watch.Start();
for (int i = 0; i < 100000; i++)
{
logger.LogWithStackFrame();
}
watch.Stop();
System.Console.WriteLine("Logging with StackFrame took :{0} seconds", watch.Elapsed.Seconds);
watch.Reset();

for (int i = 0; i < 100000; i++)
{
logger.LogWithMethodBase();
}
watch.Stop();
System.Console.WriteLine("Logging with MethodBase took :{0} seconds", watch.Elapsed.Seconds);
Console.ReadLine();
}
}

Richard O'Donnell said...

Woops- coding error. Code should be this (but it doesn't make any difference to the test result on my machine):

class LogPlay
{
private void Log(string methodName)
{
string x = methodName;
}

public void LogWithMethodBase()
{
Log(MethodBase.GetCurrentMethod().Name);
}

public void LogWithStringValue()
{
Log("LogWithStringValue");
}

public void LogWithStackFrame()
{
Log(new StackFrame().GetMethod().Name);
}

public static void Main()
{
System.Threading.Thread.CurrentThread.Priority = System.Threading.ThreadPriority.Highest;

LogPlay logger = new LogPlay();
logger.Log("Warm up");

Stopwatch watch = new Stopwatch();
watch.Start();
for (int i = 0; i < 100000; i++)
{
logger.LogWithStringValue();
}
watch.Stop();
System.Console.WriteLine("Logging with string value took :{0} seconds", watch.Elapsed.Seconds);
watch.Reset();


watch.Start();
for (int i = 0; i < 100000; i++)
{
logger.LogWithStackFrame();
}
watch.Stop();
System.Console.WriteLine("Logging with StackFrame took :{0} seconds", watch.Elapsed.Seconds);
watch.Reset();

for (int i = 0; i < 100000; i++)
{
logger.LogWithMethodBase();
}
watch.Stop();
System.Console.WriteLine("Logging with MethodBase took :{0} seconds", watch.Elapsed.Seconds);
Console.ReadLine();
}
}

Mike Hadlow said...

Richard, that's very nice. You've introduced me to a couple of things I didn't know about, the static GetCurrentMethod method on MethodBase and the Stopwatch class. And you've proved the point about the poor performance of the StackFrame class. On my machine I got these results:

Logging with string value took :0 seconds
Logging with StackFrame took :6 seconds
Logging with MethodBase took :0 seconds

There's still the problem of having to pass something to your Log method each time. In your case you have to call your log function like this Log(MethodBase.GetCurrentMethod().Name). I know it will always be the same, but it's still something that the developer has to remember each time. With the StackFrame class you can simply call Log() and then walk back up the stack to find the calling method. Hmm, performance verses convenience, the developer's dilema. One thing I will remember to do is put the call to stackFrame.GetMethod().Name after the config check to see if logging is turned on or off. That way I'll loose the performance hit when there's no logging.

Duane said...

I know this is an older post but I noticed a problem in the test code snippet: The timer is never started before running the MethodBase test. I modified it to include a watch.Start() before the final loop and changed the times to milliseconds. MethodBase is still fast, but not as fast as a static string value:

Logging with string value took :0 milliseconds
Logging with StackFrame took :919 milliseconds
Logging with MethodBase took :292 milliseconds

Anonymous said...

I was following Preet's approach. In .net 1.1 it was crashing on me in release mode while it was working fine in debug. In release, no stack frame was being returned.

Mike Hadlow said...

Anonymous, that's a very good point. When you compile in release mode the compiler often inlines method calls. That would invalidate any of these methods, except of course for the string passing one. Is there a way of marking a method as don't-inline, to stop this happening I wonder?

Richard O'Donnell said...

Mike,

Yes it is possible to stop a method being inlined.

Simply apply the following attribute:
[MethodImpl(MethodImplOptions.NoInlining)]

Mike Hadlow said...

Hi Richard,

Thanks for that. You trully are the master of the obscure corners of .NET :)