Logging? Efficiently please!

Logging is important. It allows post mortem analysis of your code. Be it for error diagnosis, to get an impression of the runtime characteristics, to trail some users work. Logging is but one option if it comes to detecting concurrency issues or in production where it is no option to attach a debugger. Logging in production of course requires the logging features to be present in release builds, yet they should have minimal performance impact if logging is switched off.

Logging is also no simple thing to do, for there are so many things to consider: Trace level, granularity, extensibility, where to log, how to configure, … . So it is prudent to check if someone has already done this work. There are actually several options, for example:

• The builtin tracing of the .NET Framework and ASP.NET tracing
• The “Logging and Instrumentation Application Block“, successor of the “Enterprise Instrumentation Framework (EIF)”, from the patterns & practices group at Microsoft.
• log4net (.NET port of the log4j framework for java)
• probably some others…

Using log4net

What do you use for logging? Log4net? Me to. Log4net is mature, easy to use, highly configurable, supports different log styles and log stores for the information, and it is kind of a standard. It is what I called in a previous post a “good framework”.

Logging with log4net is as easy as the following example, taken form the log4net manual:

using log4net;

namespace Com.Foo
{
    public class Bar
    {
        private static readonly ILog log = LogManager.GetLogger(typeof(Bar));
        
        public void DoIt()
        {
            log.Debug(“Did it again!”);
        }
    }
}

They also adress the issue of performance:

“The log4net package is designed so that log statements can remain in shipped code without incurring a high performance cost. It follows that the speed of logging (or rather not logging) is crucial. ” (log4net features)

And they provide a respective example in the log4net faq:

What is the fastest way of (not) logging?
For some logger log, writing,

log.Debug(“Entry number: ” + i + ” is ” + entry[i]);

incurs the cost of constructing the message parameter, that is converting both integer i and entry[i] to a string, and concatenating intermediate strings. This, regardless of whether the message will be logged or not.

If you are worried about speed, then write

if(log.IsDebugEnabled)
{
    log.Debug(“Entry number: ” + i + ” is ” + entry[i]);
}

This way you will not incur the cost of parameter construction if debugging is disabled for logger log. […] 

Easy to use and performance aware, right? Well, would I be asking that question if the answer where a confident “yes”?

A better way of using log4net

Whenever I began looking at performance characteristics in a project, logging in this naive way (sorry, no offense intended) was one of the first things to show up. Many projects react with simply removing logging from release builds altogether, carelessly giving away a powerfull tool – sometimes the only one – to diagnose their application in production.

The general issues with the proposed “speed optimized” version above are:

1. it is twice as much code lines per log statement (4 times if you count the curly braces)
2. it is a recommendation, not a mandatory – not to mention enforced – way of logging
3. it optimizes the usage of log4net, yet it falls short in properly observing the performance recommendations for .NET

Sidenote: It is a recomendation in .NET to avoid concatenating several string using the + operator. Rather one should use String.Concat or (with growing degree of complexity) String.Format or the StringBuilder class.

Actually this is not he only project ported from java to .NET that needs another step of “.NETification” after the first migration is done. I encountered similar issues in Spring.NET and their somewhat naive usage of reflection. NUnit for example has undergone this step: “It is written entirely in C# and has been completely redesigned to take advantage of many .NET language features, for example custom attributes and other reflection related capabilities. “

To look a bit deeper at my concerns and come up with a solution, let’s look at a slightly more complex example. Within a page class I would like to log the current request, user and possibly some error. Following the log4net documentation the code would look like this:

public class MyPage : Page
{
    private static readonly ILog log = LogManager.GetLogger(typeof(Bar));
    
    override protected void OnInit(EventArgs e)
    {
        if ((log!=null)) && log.IsDebugEnabled)
        {
            log.Debug( “Url: “ + HttpContext.Current.Request.RawUrl +
                ” User: “ +Thread.CurrentPrincipal.Identity.Name);
        }
        
        try
        {
            base.OnInit(e);
        }
        catch (Exception ex)
        {
            if (log!=null) 
                log.Error( “Exception in Page.OnInit”, ex);
            throw;
        }
    }
}

Note that I did additional checks for null. The log4net documentation does not state that GetLogger will always return a none-null value. Following defensive programming style I like to make sure a future version of log4net will not break my code.

Because logging is such a frequent thing to do I resent every line of code beyond the logging call itself. And I expect the framework to take whatever I have to log rather than having me shape the data for it. In more detail:

1. I don’t like the lingering log member. The first logging attempt will take the additional effort to remember the details of logging, go to the top of the souce file, add that member, go back to the original location in the file, and only then one will be able to finally log the data. (Am I being lazy? Sure I am. Laziness is one of the best qualities a good developer should have!)
2. I don’t like to check the trace level. Why do I have to do this just because of performance? There’s a framework. It should do that and it should do it right in the first place.
3. I don’t like this form of string concatenation. I would like the comfort of a format string. Yes, I could call String.Format. But this surely is a performance issue and again, there’s a framework to do that for me.

In accordance with my “write the client code first” approach (previous post), here is what I would expect to do:

public class MyPage : Page
{
    override protected void OnInit(EventArgs e)
    {
        LogHelper.DebugFormat(this, “Url: {0}; User: {1}”,
            HttpContext.Current.Request.RawUrl, Thread.CurrentPrincipal.Identity.Name);
        
        try
        {
            base.OnInit(e);
        }
        catch (Exception ex)
        {
            LogHelper.Error(this, ex, “Exception in Page.OnInit”);
            throw;
        }
    }
}

Looks better? You bet. However in order to work the LogHelper class is needed, one that also meets my expectations. One that looks a little like this:

public class LogHelper
{
    [Conditional(“TRACE”)]
    public static DebugFormat(object context, string format, params object[] args)
    {
        ILog log = LogManager.GetLogger(context.GetType());
        if ((log==null)) || !log.IsDebugEnabled)
            return;
        string msg= string.Format(format, args);
        log.Debug(msg);
    }
    
    [Conditional(“TRACE”)]
    public static Error(object context, Exception ex, string msg)
    {
        ILog log = LogManager.GetLogger(context.GetType());
        if ((log==null)) || !log.IsErrorEnabled)
            return;
        log.Error(msg, ex);
    }
    
    […]
}

Of course LogHelper should provide a bunch of other overloads:

• overloads that take a string or type as context, to be called by static members
• overloads that take single messages as well as a parameter lists for string concatenations
• overloads for efficient string formating
• overloads for type safety
• trace level checks for special cases
• there could be methods that are only available in debug mode
• …

So, what has been gained by this?

1. Wherever I want to log something, I can do it right away. The only price for calling a static method rather than an instance is an additional parameter context to pick the logger instance.
2. Due to the different overloads I can pass the information as I have it, relieving me of the work to prepare it for the logger.
3. The different overloads also lay the foundation for doing the trace level check within the helper class, before the cost of preparing the data (e.g. calling String.Format) has been taken.

In other words: I have to write considerably less code (logging code down by 50% and preparational code eliminated altogether). The code automatically observes the log4net recommendation for fast (not) logging and it also observes the .NET recommendation for efficient code. And last not least, it provides a multitude of logging methods tailored to my particular needs (something that is no viable option for an interface).

But wait, there’s even more! There are other logging services that can be adressed far easier in one central location. E.g.:

• Some of the helper methods could add code to enrich the information. Especially error logs could be amended with current request, user, appdomain name, session id, … .
• Some people do like method entrance/exit traces to get detailed information about the flow of control. There could be special methods tailored to that need and perhaps a special switch to distincly control it. (That switch is for me, to switch that feature off! 😈 ) 
• There’s allways the need to trace some data in more deepth. There could be helper methods that trace the complete current request information, the contents of the ASP.NET cache or session, the contents of a collection, arbitrary objects (reflecting all members), stack trace, …
• The class could register itself automatically for system events (such as error events) and thus trace application or page livecycles.
• Log4net has a problem when several instances are initialized with the same configuration and trying to write to the same files. (Which will happen in any ASP.NET application due to app domain recyclings, not to mention web garden scenarios). This can be adressed in the helper once and for all.
• …

See, log4net is good, but there is still room for a framework upon it. OK, that’s a very elaborate posting for something as simple as logging. Take it as a real world example of some of the principles outlined in the previous post (notably #1, but #3 and #0 as well).

That’s all for now folks,
AJ.NET

Advertisement