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.
This comment has been removed by the author.
ReplyDeletehi 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.
ReplyDeleteHi Preet, how's it going? And when are you going to start blogging?
ReplyDeleteI 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?
I have I think. I'll clean it up and post.
ReplyDeleteThough 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:
ReplyDeleteclass 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();
}
}
Woops- coding error. Code should be this (but it doesn't make any difference to the test result on my machine):
ReplyDeleteclass 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();
}
}
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:
ReplyDeleteLogging 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.
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:
ReplyDeleteLogging with string value took :0 milliseconds
Logging with StackFrame took :919 milliseconds
Logging with MethodBase took :292 milliseconds
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.
ReplyDeleteAnonymous, 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?
ReplyDeleteMike,
ReplyDeleteYes it is possible to stop a method being inlined.
Simply apply the following attribute:
[MethodImpl(MethodImplOptions.NoInlining)]
Hi Richard,
ReplyDeleteThanks for that. You trully are the master of the obscure corners of .NET :)