How to cleanly log messages without wasting cycles when not logging

Whether you use System.Diagnostics.Trace, log4net, or any other logger, it’s often the case that you want to allow the logging to be turned on or off at runtime. To avoid your logging to slow down your app unnecessarily when the log messages are not being collected, it’s common to use conditionals to only execute the logging paths if someone is listening. This leads to logging logic that clutters up your processing code and distracts someone reading the code from what significantly is going on. This post describes a way to try to capture the best of both worlds.

First let’s look at the most basic logging examples and discuss their problems. For simplicity I’ll just write the logging as if System.Diagnostics.Trace is what I’m using, but all the concepts and problems apply to all logging mechanisms. Keep in mind that although the Trace class has methods with the [Conditional("TRACE")] attribute on them so that calls to them don’t slow down your code if tracing is turned off, keep in mind that this is a compile-time switch rather than the runtime switch that we’re looking for. If we want trace logging as an option for the customer who receives your program/library, you need to define TRACE at compile-time, which means that even if tracing is turned off by default in your running code, your code still has all those calls to the Trace class in it.

Simplest example

In this example, we unconditionally call Trace.TraceInformation with logging messages.

var someDictionary = new Dictionary<string, int>(/* some data*/);
// some logic
Trace.TraceInformation("The dictionary has {0} elements in it.", someDictionary.Count);
Trace.TraceInformation("Dictionary contents: {0}", WriteDictionaryAsString(someDictionary));
// more logic

Although we call Trace.TraceInformation here unconditionally, internally the Trace class is only actually logging to somewhere if some trace listener is interested in these log messages. But consider what we’ve already done just by calling TraceInformation in the first place. We’ve called TraceInformation twice, with strings that must be formatted, and the second call always executes an expensive call to a method that reads through the entire dictionary and creates a large string to represent its whole contents. Now, if Trace.TraceInformation is well-written, the String.Format call it makes internally should only be called if loggers are actually recording the messages, which will save you some cycles if logging is turned off. But that will not prevent WriteDictionaryAsString from executing with its expensive code. The most straightforward way to solve this leads us to our next example.

Being smarter about how we log

Here we surround the logging calls in a conditional to prevent the expensive call to WriteDictionaryAsString if no one is listening:

TraceSwitch traceSwitch = new TraceSwitch("YourLoggingSwitch", "Some Description");
var someDictionary = new Dictionary<string, int>(/* some data*/);
// some logic
if (traceSwitch.TraceInfo)
{
    Trace.TraceInformation("The dictionary has {0} elements in it.", someDictionary.Count);
    Trace.TraceInformation("Dictionary contents: {0}", WriteDictionaryAsString(someDictionary));
}
// more logic

This is an improvement, because a quick boolean check is really cheap which makes the non-logging scenario very fast by avoiding the calls to TraceInformation altogether and especially that expensive WriteDictionaryAsString call. But look how we now have 6 lines of logging code instead of 2. Yuck. We can improve on this by finding a middle-ground.

Building the smarts into the system

Note that WriteDictionaryAsString is necessary because Dictionary<TKey, TValue> doesn’t have a useful ToString() method. If it did, we could just pass the dictionary instance to TraceInformation, which could call ToString() on the object only if tracing were turned on. Then we’d be back to just two quick calls to TraceInformation, which don’t really do anything inside unless logging is turned on. This would be ideal, but Dictionary doesn’t support it, and often you have complex structures of your own to emit that don’t have ToString() methods that behave this way.

So let’s come up with a new way to accomplish the same thing. Imagine what we could do if we did:

var someDictionary = new Dictionary<string, int>(/* some data*/);
// some logic
Trace.TraceInformation("The dictionary has {0} elements in it.", someDictionary.Count);
Trace.TraceInformation("Dictionary contents: {0}", someDictionary.DeferredToString());
// more logic

That looks downright readable again. Now here’s how we make this work well and fast:

/// <summary>
/// Extension methods for deferred serialization of various object types to strings.
/// </summary>
public static class DeferredToStringTools {
    /// <summary>
    /// Prepares a dictionary for printing as a string.
    /// </summary>
    /// <remarks>
    /// The work isn't done until (and if) the 
    /// <see cref="Object.ToString"/> method is actually called, which makes it great
    /// for logging complex objects without being in a conditional block.
    /// </remarks>
    public static object DeferredToString<K, V>(this IEnumerable<KeyValuePair<K, V>> keyValuePairs) {
        return new CustomToString<IEnumerable<KeyValuePair<K, V>>>(keyValuePairs, dictionarySerializer);
    }

    // Add as many overloads of DeferredToString as you want to this class,
    // one for each type of object you want to emit as part of logging. 


    private static string dictionarySerializer<K, V>(IEnumerable<KeyValuePair<K, V>> pairs) {
        var dictionary = pairs as IDictionary<K, V>;
        StringBuilder sb = new StringBuilder(dictionary != null ? dictionary.Count * 40 : 200);
        foreach (var pair in pairs) {
            sb.AppendFormat(CultureInfo.CurrentCulture, "t{0}: {1}{2}", pair.Key, pair.Value, Environment.NewLine);
        }
        return sb.ToString();
    }

    /// <summary>
    /// Wraps an object in another object that has a special ToString() implementation.
    /// </summary>
    /// <typeparam name="T">The type of object to be wrapped.</typeparam>
    private class CustomToString<T> {
        T obj;
        Func<T, string> toString;

        public CustomToString(T obj, Func<T, string> toString) {
            if (toString == null) throw new ArgumentNullException();
            this.obj = obj;
            this.toString = toString;
        } 

        public override string ToString() {
            return toString(obj);
        }
    }
}

Note that the code above uses a couple of C# capabilities unique to .NET 3.5. If you are targeting .NET 2.0 you can still do this, but the syntax will be slightly different.

So there you have it. You can call Trace.TraceWarning, TraceInformation, etc. all you want (ok, still within reason) and pass it strings with {0} placeholders and objects that must be written out as strings, and those objects without adequate ToString() methods can leverage this facility to benefit from deferred serialization just like any other type with an adequate ToString() method.