Thoughts on System.Diagnostics Trace vs. Common.Logging

While working on the final bits for Common.Logging 2.0 I just looked a bit closer into NET’s trace model and tried to compare it to Common.Logging. I must admit that, being a long-time user of first log4net and then Common.Logging, I never much cared about <system.diagnostics>. Revisiting assumptions from time to time is a good habit, thus I dived into .NET tracing. Here’s what I found…

Configure and use <system.diagnostics>

The .NET trace system basically works by using TraceSources (="Logger" in log4net) to write events to a list of TraceListeners (="Appenders") that decide whether a message to log by consulting a list of TraceFilters. This could be useful, alas there is no "batch" configuration possible, means you need to configure this chain for each TraceSource. Here's a minimum example what one needs to do:

<system.diagnostics>
    <sharedListeners>
        <add name="myListener"
             type="MyTestTraceListener, MyAssembly" />
    </sharedListeners>
    <sources>
        <source name="mySource" switchValue="All">
            <listeners>
                <add name="myListener" />
            </listeners>
        </source>
    </sources>
</system.diagnostics>    

Your code will then look like this:

class MyClass
{
    readonly TraceSource trace = new TraceSource("mySource");
    void Foo(object someArg)
    {
        try
        {
            Bar(someArg);
        }
        catch (Exception ex)
        {
            trace.TraceEvent(TraceEventType.Information, -1,
            "error arg={0}:{1}", someArg, ex);
        }
    }

    void Bar(object someArg) { /* do something */}
}

A nice tutorial on tracing is given in this blog, some criticism is found here.

Performance Considerations

Of course you don’t want to pay much performance costs for your logging infrastructure. Fortunately tracing doesn’t cost you too much. I wrote some tests in Common.Logging to compare both and found Common.Logging twice as fast as Trace. Note, that we are talking about 2s vs. 4s for passing 100.000.000 log entries through the chain. I do not think that this is an issue for anyone except for applications generating an insane number of log entries.

Things get interesting when evaluating a log message becomes expensive. Take for example the line from the example above:

  trace.TraceEvent(TraceEventType.Information, -1,
                           "error arg={0}:{1}", someArg, ex); 

Somewhere within the tracing framework, the passed string and arguments must be evaluated and string.Format() gets called. But you do not want this to happen unless that message *really* gets logged – string.Format() calls both, someArg.ToString() and ex.ToString(), which might be very expensive to calculate!

To be safe, you need to wrap all your calls by

if ( trace.Switch.ShouldTrace(TraceEventType.Information) )
{
 trace.TraceEvent(TraceEventType.Information, -1,
              "error arg={0}:{1}", someArg, ex);
} 

Unfortunately this doesn’t help in all cases. Most often you want all messages from all (or at least most) modules but only the informational ones (not the verbose). You can configure this using a filter:

<system.diagnostics>
    <sharedListeners>
        <add name="myListener"
             type="MyTestTraceListener, MyAssembly">
            <filter type="System.Diagnostics.EventTypeFilter"
                    initializeData="Information"/>
        </add>
    </sharedListeners>
    <sources>
        <source name="mySource" switchValue="All">
            <listeners>
                <add name="myListener" />
            </listeners>
        </source>
    </sources>
</system.diagnostics>

Using the configuration above, all messages will be passed into “myListener”, who’s filter will drop all messages above the information level. Unfortunately there is another issue: The framework automatically adds a DefaultTraceListener to all configured <source>s that will happily log all messages. To avoid this you need to write

<source name="mySource" switchValue="All">
    <listeners>
        <!-- prevent DefaultTraceListener from being added -->
        <clear />
        <add name="myListener" />
    </listeners>
</source>

I wrote some performance tests simulating the case where we only want to log Warnings. Messages are emitted at “Info” level, but the configuration should restrict messages to “Warning”s. On my box this resulted in

Time:00:00:01.9640000 - log.InfoFormat + NoOpLogger
Time:00:00:04.8410000 - traceSource.TraceEvent + unconfigured TraceSource
Time:00:00:03.6140000 - log.InfoFormat
Time:00:00:12.7380000 - traceSource.TraceEvent

As you can see, using tracing gets significant slower using the configuration above. Frankly I could not figure out what causes this. Things become unacceptable as soon as you forget to remove the DefaultTraceLogger:

Time:00:00:00.6670000 - log.InfoFormat + NoOpLogger 
Time:00:00:02.2950000 - traceSource.TraceEvent + unconfigured TraceSource 
Time:00:00:02.2250000 - log.InfoFormat 
Time:01:00:23.8650000 - traceSource.TraceEvent <= not kidding here!

For this reason, Common.Logging introduced a new signature for logging leveraging the power of lambda expressions:

  log.Info( m=>m("some logger info {0}", (object)myObj) )

Using this syntax you will always be on the safe side. Common.Logging will take care, that the message will only be evaluated in case it really gets logged.

Conclusion

What bothers me most is the pain of configuring & using the trace framework. Here are the major pain points I found with the built-in tracing framework:

• It is possible to share listeners, but you need to configure the list of listeners for each TraceSource.
• It is impossible to configure a default listener to be used by all TraceSources
• There is no logging of exception objects possible
• One can instruct a TraceListener to append the current callstack to the message, but this will include the System.Diagnostics stack(!)
• No easy way for "batch" configuring log levels for multiple sources (like in log4net logger hierarchies), each source must be explicitly configured with level+listener
• As soon as one configures the listeners for a TraceSource, a DefaultTraceListener will also be added to the list, causing each message to be logged to OutputDebugString as well (add a <clear/> element to the sample above.
• It is incredible verbose to use, both tracing and configuring

If one insists on avoiding a dependency on Common.Logging or log4net, go with tracing – you’ve been warned.

For all others I recommend grabbing Common.Logging. It allows you to defer the decision of which logging framework to use until the moment you deploy your application. Simply plug in any other logging system you might want to use. If you need to turn off logging at all, configure NoOpLoggerFactoryAdapter and minimize the costs of your log statements to almost zero - guaranteed!