January 27, 2009

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:

        <add name="myListener"
             type="MyTestTraceListener, MyAssembly" />
        <source name="mySource" switchValue="All">
                <add name="myListener" />

Your code will then look like this:

class MyClass
    readonly TraceSource trace = new TraceSource("mySource");
    void Foo(object 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:

        <add name="myListener"
             type="MyTestTraceListener, MyAssembly">
            <filter type="System.Diagnostics.EventTypeFilter"
        <source name="mySource" switchValue="All">
                <add name="myListener" />

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">
        <!-- prevent DefaultTraceListener from being added -->
        <clear />
        <add name="myListener" />

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.

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!


metaman said...

I've never come across Common.Logging before but sounds really useful. Shame that NHibernate doesn't use this than rely on dependency to Log4Net. Guess I could do my own build?

Erich Eichinger said...

u can always make your own build - of course this comes with some cost when upgrading. Fabio Maulo plans to remove log4net from NHibernate. You might want to ping him and vote for Common.Logging at his blog ;-)

Bhushan said...

Scared to see this message


Kenneth Xu said...

Nice to see this article and thanks for the great work! Glad to know that I made right decision two years ago. Common.Logger will be my favorite logging bridge for many years to come.

On feature request, I needed an in memory sink for unit testing and wrote one myself to start with. But I would like to see this as a build in support of Common.Logging.

Common.Logging for .Net and It's Use in Unit Test

Leo said...

For a fair speed comparison with .Net you may want to add a line:
<remove name="Default"/>

Under <listeners> element in configuration.

Erich Eichinger said...

@Leo: You are right that this is one of the major reasons for the performance problem. But this is my point - the default settings of Diagnostics.Trace suck and to me definitely break the principle of least surprise.

xor said...

Erich, about this lambda syntax. Why not simply write it like this?

log.Debug( ()=> String.Format( ... ) );

You really don't need this "m" parameter - it's enough to have a function that returns string value.

Erich Eichinger said...

@xor I struggled quite a while with this, but in the end I liked the current solution more because it reduces the code noise. I found having to write string.Format() all the time is annoying. m=>m is shorter

xor said...

Then, perhaps, it worth making two versions with delegates of different signature. Just in case when m() = String.Format() is not enough.

Erich Eichinger said...

do you have any concrete usecase on your mind?

)\/( said...

I'm looking at writing a logging interface am leaning toward lambdas like Xor. But I have to concede Erich's comment - I don't know of a use case.

When you start getting longer (and more practical) messages, like:

log.Debug(m => m(
"Unexpected failure processing at record {0} of {1}. Requested date = {2:yyyyMMdd}",

...I'm not sure the extra weight of string.Format really is that big of a burden.

I'm also trying anonymous types:

Message = "Unexpected failure processing",
TotalNumRecords = records.Count(),
NumProcessed = i,
ProcessDate = processDate

...which has some drawbacks, like having to evaluate "records.Count" and not being able to format "processDate". It's also
"slower" but not exactly "slow", IMO.

Anyway, I wanted to add that, though way late to this party. Kinda wandering about looking for ideas to maximize clarity and minimize the whole interface.

wageoghe said...

I thought I was late to the game here, but I can see there was just a new comment made yesterday!

If you haven't seen it already, you might have a look at Castle's logging abstraction for System.Diagnostics.TraceSource-based logging. It is pretty straightforward, but they added the capability to have hierarchical TraceSources. Assuming you ask for a TraceSource with a "hierarichical" name, like a fully-qualified class name:

TraceSource ts = new TraceSource("TopNameSpace.MiddleNameSpace.BottomNameSpace.Class");

Then their logic (where they are actually in control of creating the new TraceSource in response to a LogManager.GetLogger(string name) type of call) attempts to see if there is a configured TraceSource for the requested name. If not, they trim the name from the right, successively removing the class name and the nested namespaces. If they ever determine that there is a configured TraceSource, then it is used as the basis to create the requested TraceSource. So, you could configure a TraceSource called "TopNameSpace" in your app.config. Requesting loggers/TraceSources for names that are descended from "TopNameSpace" via Castle's extra logic will result in an appropriately named TraceSource being created (i.e. fully qualified) and configured to match the first-found ancestor. So, in the case above, the TraceSource returned for "TopNameSpace.MiddleNameSpace.BottomNameSpace.Class" would have the requested name, but would be configured (Switch params and Listseners) as "TopNameSpace" is configured.

With that extra logic, it becomes possible to configure one logger per namespace or namespace level, or whatever you want. Of course, you are not limited to class names and namespace names, just as log4net is not limited. If you configure a TraceSource called "aaa" and then request TraceSources for "aaa.bbb" and "aaa.bbb.ccc", you will get the same hierarchical processing.

I don't actually use Castle, but I found that logic and implemented in a TraceSource wrapper and it works pretty well. I also added the ability to configure a TraceSource called "*" (just like log4net and NLog). If the requested TraceSource does not find anything in the hierarchy AND "*" is configured, then the you will get a TraceSource configured like "*".

I wonder if it would be useful for Common.Logging to have a TraceSource abstraction, similar to Castle's?

KyoungSang Yu said...

In my humble opinion, it is not a fair comparison. First, you set a log level to “Logger,” however you set to “Listener”, which is not “Logger” but “Appenders.” Second, Log.Info call will filter the log only once. However, your test code does not set the filter to TraceSoucce but TraceListener. So, bulk of unnecessary call to TraceSource and TranceListener was generated. Your test code should be like this to compare “apple to apple,” not “apple to orange.”

// source level filter required
TraceSource traceSource = new TraceSource("bla", SourceLevels.Warning);

traceSource = new TraceSource("DiagnosticsTracePerformanceTest");
traceSource.Switch.Level = SourceLevels.Warning;
listener = (MyTestTraceListener) traceSource.Listeners[0];

The test result on my machine is:

Time:00:00:00.4420253 - log.InfoFormat + NoOpLogger
Time:00:00:01.4480828 - traceSource.TraceEvent + unconfigured TraceSource
Time:00:00:00.7540432 - log.InfoFormat
Time:00:00:01.4100806 - traceSource.TraceEvent

Of course, Common.Logging was much faster than .NET trace. However I think it is not a problem in performance.

p.s. I’m not a native English speaker. Excuse my ugly English. Thanks.

Juan Pablo de Juan said...

Great article!!


Asava Samuel said...

This is a great logging library:

sgryphon said...

Arguments passed to trace.TraceEvent() *are* only evaluated if the message is actually logged. Using the lambda syntax is an interesting variant, but doesn't really save anything (either way the costly expression is only run if the message is actually logged).

Also, of course you can log exception objects (so I don't know why you said you can't) -- in fact, you do it in the MyClass example where the exception is the last argument!

I presume you mean that there is no overload that explicitly takes an Exception parameter, you have to always log it as trace.TraceEvent(TraceEventType.Error, 0, "{0}", ex).