So, thought I'd share my awesome logging technique in .Net. Here's your basic super-dumb program... a main method that calls into "MyMethod" and writes a value out to the screen entered by the user (which must be an integer).
class Program
{
static void Main(string[] args)
{
MyMethod(Console.ReadLine());
}
public static void MyMethod(string value)
{
try
{
Console.Write(Int32.Parse(value));
}
catch (Exception)
{
Console.WriteLine("That wasn't a number...");
}
}
}
So, you want to log/trace your method entries and method exits. Here's the naive approach:
class Program
{
static void Main(string[] args)
{
MyMethod(Console.ReadLine());
}
public static void MyMethod(string value)
{
Logger.LogEnter("MyMethod");
try
{
Console.Write(Int32.Parse(value));
}
catch (Exception)
{
Console.WriteLine("That wasn't a number...");
}
Logger.LogExit("MyMethod");
}
}
public class Logger
{
public static void LogEnter(string methodName)
{
Console.WriteLine(string.Format("Enter {0}", methodName));
}
public static void LogExit(string methodName)
{
Console.WriteLine(string.Format("Exit {0}", methodName));
}
}
What sucks about that? Well, you've written your method name 3 times! Plus, you have to assure that your catch logic captures all cases and never returns early. That's a very limiting approach.
The next approach, using the stack frame:
class Program
{
static void Main(string[] args)
{
MyMethod(Console.ReadLine());
}
public static void MyMethod(int value)
{
Logger.LogEnter();
{
Console.Write(Int32.Parse(value));
}
catch (Exception)
{
Console.WriteLine("That wasn't a number...");
}
Logger.LogExit();
}
}
public class Logger
{
public static void LogEnter()
{
System.Diagnostics.StackFrame frame = new System.Diagnostics.StackFrame(1);
Console.WriteLine(frame.GetMethod().Name);
}
public static void LogExit()
{
System.Diagnostics.StackFrame frame = new System.Diagnostics.StackFrame(1);
Console.WriteLine(frame.GetMethod().Name);
}
}
Well, that's pretty cool, and solves one of the above problems (of writing your method name over and over), but aside from being an INCREDIBLY expensive call going into the stack frame, you're still stuck with making sure you don't leave your method early. Sure, you can mitigate that with proper use of a try/finally block... but you're about to be bitten by something FAR worse: your compiler and your Jitter. Guess what... they know better than you once in release mode. They're going to do all sorts of crazy-smart stuff like sometimes optimizing out your method altogether. This approach is going to work just fine in debug mode, but once you go release, you're going to find out that your little method is going to (without your control) optimize out your method depending on its complexity. Now, your stack walk is going to be completely wrong and your logging is going to write out "Main" when you expected "MyMethod".
So, balancing out all the problems, what's a good approach? Well, I have one.
class Program
{
static void Main(string[] args)
{
MyMethod(Console.ReadLine());
}
public static void MyMethod(string value)
{
using (Logger.Enter("MyMethod"))
{
try
{
Console.Write(Int32.Parse(value));
}
catch (Exception)
{
Console.WriteLine("That wasn't a number...");
return;
}
}
}
}
public struct Logger : IDisposable
{
private string _methodName;
public static Logger Enter(string methodName)
{
Logger logger = new Logger();
logger._methodName = methodName;
Console.WriteLine("{0} enter", logger._methodName);
return logger;
}
public void Dispose()
{
Console.WriteLine("{0} exit", this._methodName);
}
}
Wow... So, now, when you enter your method, you just have one copy of your method name... good tradeoff. And, no matter how you leave your method, you're going to get your method enter/exit thanks to the IDisposable pattern + a using block.
So... why a struct? Well, let's say you're in a high-performance application and somebody really has a bug-up-their-butt about object instantiations on the heap... well, guess what... this gets allocated on the stack, and gets cleaned up when you leave this scope. Oh! But there's a hole in my logic! When I cast to an IDisposable in at the end of the using block, it gets boxed and dropped on the heap! Oh, but yay, we have smart people over in the compiler... This dude looked through the IL and I verified that what he put forth is true. Straight-up callvirt on the Dispose function in the case of structs. Brilliant.
http://haacked.com/archive/2006/08/11/TheUsingStatementAndDisposableValueTypes.aspx
So, here's the overall usage of this awesomeness, including inline tracing, for good measure:
class Program
{
static void Main(string[] args)
{
MyMethod(Console.ReadLine());
}
public static void MyMethod(string value)
{
using (Logger logger = Logger.Enter("MyMethod"))
{
try
{
logger.Trace("Before parsing");
Console.Write(Int32.Parse(value));
logger.Trace("Parsed successfully");
}
catch (Exception)
{
Console.WriteLine("That wasn't a number...");
logger.Trace("Found a bad number");
return;
}
}
}
}
public struct Logger : IDisposable
{
private string _methodName;
public static Logger Enter(string methodName)
{
Logger logger = new Logger();
logger._methodName = methodName;
Console.WriteLine("{0} enter", logger._methodName);
return logger;
}
public void Trace(string operation)
{
Console.WriteLine("{0} : {1}", _methodName, operation);
}
public void Dispose()
{
Console.WriteLine("{0} exit", this._methodName);
}
}
You can expand upon this amazingly simple, and low-impact method of doing effective logging and tracing of your methods where the only compromise is keeping track of your method name in one place, conveniently very close to the actual name of the method. What you gain is one very effective logging and tracing technique. What amazes me is that I've seen resistance to this method. Sigh...
No comments:
Post a Comment