Sunday, July 27, 2008

My logging technique is supreme

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();

        try
        {
            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...

Monday, July 7, 2008

Regional Vindication

Thank you, Jeff

I've long been an opponent of the over-use of regions in code in Microsoft's IDE.  It serves a unique purpose of hiding undesirable code, but it also serves the cost of hiding undesirable code.

So few developers know when to use this sort of uber-comment correctly.  I've always felt that comments, themselves, often serve as a cover for bad code.  I've actually seen regions used to separate out test functions by developer who implemented them.  I put a stop to that quickly in code review.

Distracted... I saw a spider coming down from the ceiling in front of the TV (watching The Big Bang Theory) and I did something messed.  I grabbed him by the web up high, and carried him at arms-length to the toilet where I flushed him into his new sanitary sewer home.

So, yes.  Regions.  From some unknown project in coding land.

bad regions

Seriously... how is that useful?  They even spent time counting the stars to line up properly in somebody's IDE.

I'd love to see the line numbers on that file.  I'm guessing that the "Properties" section has half a dozen public properties, 3 public fields, and a couple private members.  Constructor has one vestigial empty constructor.  Methods has 19 private functions, and 2 newly-public ones.  2 private variables are now public members.

My semi-educated guess here is actually not that far off.  The details are not important, but it points to a maintenance nightmare... not to mention readability.  Look at that code and tell me what it does.  You have exactly the name of the class to go by.  No comment on the class.... Why not a quick grep of the method names for help?

My modus operandi is to see a new code file and hit Ctrl-M,O.  This reduces the class down to its most basics:  the class name, its properties and the methods.  If all that doesn't fit on 2 pages of scrolling, your class is too big.  It does too much.  It's not one cohesive functional thingy.  If I can't describe it in an elevator pitch... or if it has, in the name something like "manager", "utilities", "common", "tasks"...  it's doing too much.  Regions are a poor-man's organization.

I believe, at this point, the languages facilitate a class definition that can be inferred from a glance.  Comments should compliment the code, not explain what should be clearly visible.  I'll get into, later, the use of comments externally, as well is within a function.

Silverlight Streaming Service

I'm pretty proud of this. This is a great cross-team integration between some folks in another building and our team at Publisher. Not to toot my own horn, but I did quite a bit to make this work.

Via ars Technica
The program is the first time a Windows Live service that gives access to the Microsoft adCenter Publisher platform has been opened to developers. The selected participants will become adCenter Publisher account holders, as the account provisioning into the ads platform is done directly when they decide to enable ads in their SLS-based video playback options.

US testers who fill out a W-9 form have the opportunity to make money from their videos with this pilot program. The video content uploaded to Silverlight Streaming plays back with contextual ads relevant to the playback experience, based on keywords provided.

So, if you've got a blog, and have some movies you run, and you don't want to use YouTube (understandable given the latest court decision), you have a great option, with a couple bucks coming your way. Go ahead and sign up. We made it REAL easy, and you've got a great shot of getting in if you have a site that can pass the smell test.

White Ninjas

This just proves, you even have to watch for the white ninjas.



Of course, the original White Ninja: