Method entry/exit logging

Article
12/17/2008

Frequently you need to add in some form of logging in your code on method entry and exit points, and typically this is done in a way which over-burdens you (the developer) with a fair bit of extra code.

Now, the universal panacea would be to be able to just attach logging around your code without having to change a line, but unless you are using a third party framework which provides some form of AOP style code injection such as PostSharp you are out of luck. Assuming you (a) want to add in logging and (b) don't want to take a dependency on another project, what's the easiest way to add in method logging? I'll aim to show that in this blog entry.

First off though lets define some pre-requisites that our logging should have :-

As easy to add as possible by limiting the amount of code that is needed
Simple to extend with extra information – such as logging method timings
Easy to switch on and off, and lightweight too

I’ll hopefully satisfy each of these in the upcoming sections.

Apologies for the length of this post, but it just seemed useful to go into a load of detail on this seemingly simple topic!

#1 – Easy to Use

To satisfy #1 I’ll employ a fairly standard model – that of using a disposable class. In it’s simplest incarnation you could write a class such as the following to log method entry and exit :-

 public class MethodLogger : IDisposable
{
    public MethodLogger(string methodName)
    {
        _methodName = methodName;

        // Log method entry here
    }

    public void Dispose()
    {
        // Log method exit here
    }

    private string _methodName;
}

Obviously this won’t actually do any logging but shows the principle. To use the above in your code you might alter your method as follows :-

 public void YourCode()
{
    using (new MethodLogger("YourCode"))
    {
        // Write your stuff here
    }
}

So here all I’ve done is added the using clause around the code within the method. The MethodLogger class will take care of emitting entry data in its constructor, and as it implements IDisposable we can write code in the Dispose() method to emit the method exit information. That’s one line less code you need to add into your method in order to emit this end of method information, so I reckon that’s #1 just about sorted. So far so good.

Just as an aside – I’ve used this pattern elsewhere over the years. One favourite spot was changing the Cursor in a WinForms app – my CursorChanger class would simply get the current cursor in its constructor, replace this with the wait cursor, and then reset the cursor to what it was originally in the Dispose method. Job done.

#2 – Easy to extend

Now at the moment I don’t feel my MethodLogger class is really much good – we’ll ignore the fact that nothing comes out of it for the moment, I’m talking about the usage of the class. I can think of several options you might want to choose when constructing the logger which are not mutually exclusive :-

Log Entry
Log Exit
Log Time In Function

You may be able to think up some more. This seems like an ideal place for an Enum. In addition I’m not so happy with the code I wrote above as it’s always creating a MethodLogger for me. What if method logging is turned off for some reason? There’s not much need to construct a class which does nothing is there, so how could I ensure that an object is only instantiated as needed? And what about the call site where I have the using clause – I shouldn’t need to change the call site if logging is turned off, should I?

If you look at the code emitted into an assembly by the using statement, it looks much like the following :-

 IDisposable obj = new MethodLogger("YourCode");
try
{
    // Write your stuff here
}
finally
{
    if (null != obj)
        obj.Dispose();
}

I can use this null check to my advantage. Rather than use new MethodLogger(…) I can create a static method which can be used to return either a MethodLogger instance, or null if logging has not been enabled. Thus the call site remains the same. Cool. The updated MethodLogger would then be something like this (I’ll get to turning the class off/on in section #3) :-

 /// <summary>
/// Options used when logging a method
/// </summary>
[Flags]
public enum LogOptions
{
    /// <summary>
    /// Log entry into the method
    /// </summary>
    Entry = 0x01,
    /// <summary>
    /// Log exit from the method
    /// </summary>
    Exit = 0x02,
    /// <summary>
    /// Log the execution time of the method
    /// </summary>
    ExecutionTime = 0x04,
    /// <summary> 
    /// Log all data 
    /// </summary> 
    All = 0xFF
}

public class MethodLogger : IDisposable
{
    /// <summary>
    /// Log method entry 
    /// </summary>
    /// <param name="methodName">The name of the method being logged</param>
    /// <param name="options">The log options</param>
    /// <returns>A disposable object or none if logging is disabled</returns>
    public static IDisposable Log(string methodName, LogOptions options)
    {
        // If logging off then return null, else
        return new MethodLogger(methodName, options);
    }

    /// <summary>
    /// Ctor now private - just called from the static Log method
    /// </summary>
    /// <param name="methodName">The name of the method being logged</param>
    /// <param name="options">The log options</param>
    private MethodLogger(string methodName, LogOptions options)
    {
        _methodName = methodName;
        _options = options;

        if ((_options & LogOptions.ExecutionTime) == LogOptions.ExecutionTime)
        {
            _sw = new Stopwatch();
            _sw.Start();
        }

        if ((_options & LogOptions.Entry) == LogOptions.Entry)
        {
            // Log method entry here
        }
    }

    /// <summary>
    /// Tidy up
    /// </summary>
    public void Dispose()
    {
        if ((_options & LogOptions.ExecutionTime) == LogOptions.ExecutionTime)
        {
            _sw.Stop();

            // Log _sw.ElapsedMilliseconds
        }

        if ((_options & LogOptions.Exit) == LogOptions.Exit)
        {
            // Log method exit here
        }
    }

    private string _methodName;
    private LogOptions _options;
    private Stopwatch _sw;
}

That’s starting to look much better to me. I have defined the LogOptions enum and provided Entry, Exit and ExecutionTime as the available options. There may well be more you would wish to consider.

I’ve also changed the visibility of the MethodLogger constructor so that it’s now only possible to create one of these when using the static Log method. For the client the code is a little different but still very legible :-

 public void YourCode()
{
    using (MethodLogger.Log("YourCode", LogOptions.All))
    {
        // Write your stuff here
    }
}

You may also have noticed that I’m also constructing a Stopwatch instance within the MethodLogger class if you choose to log the method time. There are other things you might want to do here – and all of them have little bearing on the caller. Maybe you want to update a performance counter based on the method name, so you can see statistics such as ‘number of calls’, ‘average execution time’, ‘number of calls/sec’ and so on. There’s no reason why you couldn’t hide this behind the facade of the MethodLogger.Log call.

#3 – Easy to switch on and off, lightweight too

So at present there is no code within the class to dial up or down the logging, and as there’s a logging framework within .NET already (the much improved as of .NET v2 System.Diagnostics classes – see here for a great intro by yours truly) I might as well use that as it includes the ability to turn on and off logging by using a switch.

If you’ve not boned up on the TraceSource class I’d urge you to read the article I linked to above, as knowledge of trace sources is necessary for the following section.

So, in order to be able to trace data somewhere we need a trace source. The MethodLogger class will use this source to raise events – such as the entry and exit events shown above. If you look at the TraceSource class you’ll notice that the methods typically include an integer ID – this could be used as some form of method name map, but in my code I’ve ignored this parameter and set to zero. With the addition of the TraceSource the call to MethodLogger would look something like this :-

 using (MethodLogger.Log("YourCode", LogOptions.All, source))
{
    // Write your stuff here
}

Notice the last parameter – this is our trace source.

Now you might be wondering why I pass through the name of the method into the Log call. Couldn’t I just use reflection to get the call stack and work out which method I’m in? Well yes, I could, but do you know how much overhead that gives at runtime? To check this out I wrote a simple test which made 100,000 calls to a method. One method I passed a string value to which simulates the name of the method from my logging class. The other used the StackTrace/StackFrame/MethodInfo classes in .NET. For 100,000 iterations the string based method barely registered – I measured 1ms. For the StackTrace based one I measured a whopping 5126ms – yes, that’s several orders of magnitude slower.

Now think about this – the logging code is likely to get into all methods. It needs to be as lean and mean as possible. Whilst you pay for this in the fact you need to use a method name as part of the method call, I believe the benefit in speed far outweighs this minor bother.

So, it’s fairly lightweight, but can I switch it on and off? Of course – you just need a bit more code in the Log method which works out whether the options selected (i.e. LogOptions), and the logging level on the TraceSource will result in anything being emitted. If the log level is set too low (such as just for Critical errors) there is no need to construct our disposable logger class – as it’s output will never be written out. Again a little work up front within the code reaps benefits of potentially fewer objects constructed and hence less work to do. The check inside the Log function is shown below :-

 /// <summary>
/// Log method entry 
/// </summary>
/// <param name="methodName">The name of the method being logged</param>
/// <param name="options">The log options</param>
/// <param name="source">The TraceSource that events are written to</param>
/// <returns>A disposable object or none if logging is disabled</returns>
public static IDisposable Log(string methodName, LogOptions options, TraceSource source)
{
    IDisposable logger = null;

    // Check if ExecutionTime logging is requested, and if so log if Verbose 
    // logging (or greater) is chosen
    bool shouldCreate = ((options & LogOptions.ExecutionTime) == LogOptions.ExecutionTime) 
      & ((uint)source.Switch.Level > (uint)SourceLevels.Warning);

    // If not logging ExecutionTime, see if ActivityTracing is on, and if so log only 
    // if Entry or Exit tracing is requested
    if (!shouldCreate)
        shouldCreate = ((source.Switch.Level & SourceLevels.ActivityTracing) 
                         == SourceLevels.ActivityTracing) &
            (((options & LogOptions.Entry) == LogOptions.Entry) | 
             ((options & LogOptions.Exit) == LogOptions.Exit));

    // Check if we actually need to log anything
    if (shouldCreate)
        logger = new MethodLogger(methodName, options, source);

    // Will return null if no method logger was needed - which will effectively 
    // be ignored by a using statement.
    return logger;
}

So now we have a trace source, have code that checks if we need to be created, the next bit is to write out the log events which is pretty trivial. All I need to do is call the appropriate method on the TraceSource class and we’re away. The final incarnation of the code is shown below :-

 public class MethodLogger : IDisposable
{
    /// <summary>
    /// Log method entry 
    /// </summary>
    /// <param name="methodName">The name of the method being logged</param>
    /// <param name="options">The log options</param>
    /// <param name="source">The TraceSource that events are written to</param>
    /// <returns>A disposable object or none if logging is disabled</returns>
    public static IDisposable Log(string methodName, 
                                  LogOptions options, 
                                  TraceSource source)
    {
        IDisposable logger = null;

        // Check if ExecutionTime logging is requested, and if so log if Verbose 
        // logging (or greater) is chosen
        bool shouldCreate = ((options & LogOptions.ExecutionTime) == 
                              LogOptions.ExecutionTime) & 
                              ((uint)source.Switch.Level > (uint)SourceLevels.Warning);

        // If not logging ExecutionTime, see if ActivityTracing is on, and if so 
        // log only if Entry or Exit tracing is requested
        if (!shouldCreate)
            shouldCreate = ((source.Switch.Level & SourceLevels.ActivityTracing) 
              == SourceLevels.ActivityTracing) &
                (((options & LogOptions.Entry) == LogOptions.Entry) | 
                 ((options & LogOptions.Exit) == LogOptions.Exit));

        // Check if we actually need to log anything
        if (shouldCreate)
            logger = new MethodLogger(methodName, options, source);

        // Will return null if no method logger was needed - which will 
        // effectively be ignored by a using statement.
        return logger;
    }

    /// <summary>
    /// Ctor now private - just called from the static Log method
    /// </summary>
    /// <param name="methodName">The name of the method being logged</param>
    /// <param name="options">The log options</param>
    private MethodLogger(string methodName, LogOptions options, TraceSource source)
    {
        _methodName = methodName;
        _options = options;
        _source = source;

        if ((_options & LogOptions.ExecutionTime) == LogOptions.ExecutionTime)
        {
            _sw = new Stopwatch();
            _sw.Start();
        }

        if ((_options & LogOptions.Entry) == LogOptions.Entry)
            _source.TraceEvent(TraceEventType.Start, 0, methodName);
    }

    /// <summary>
    /// Tidy up
    /// </summary>
    public void Dispose()
    {
        if ((_options & LogOptions.ExecutionTime) == LogOptions.ExecutionTime)
        {
            _sw.Stop();
            _source.TraceInformation("Method {0} execution time {1}ms", 
                                     _methodName, 
                                     _sw.ElapsedMilliseconds);
        }

        if ((_options & LogOptions.Exit) == LogOptions.Exit)
            _source.TraceEvent(TraceEventType.Stop, 0, _methodName);
    }

    private string _methodName;
    private LogOptions _options;
    private Stopwatch _sw;
    private TraceSource _source;
}

Apologies for the length of this post on something so seemingly trivial.

There’s still more you can do to the code – for example you might want to log the parameters on method entry, but I’ll leave that as an exercise for the reader.

Hopefully this has proven that adding in method entry/exit code in .NET isn’t too onerous a task, and you can add on extra capabilities such as performance counters fairly easily to the model presented here.

Method entry/exit logging

#1 – Easy to Use

#2 – Easy to extend

#3 – Easy to switch on and off, lightweight too

Additional resources