AJ's blog

November 3, 2006

Logging? Efficiently please!

Filed under: .NET, .NET Framework, Software Development — ajdotnet @ 9:58 pm

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:

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! :twisted:
  • 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

About these ads

5 Comments »

  1. First, I want to point out that the deferred formatting of logging messages is already available on the ILog interface. Instead of calling log.Debug(“thing ” + i), you can call log.DebugFormat(“thing {0}”, i) and you’ll only incur the cost of the call-frame setup and teardown. There’s even a version that takes the IFormatProvider so you can insure (as you should) that messages are logged in your perferred locale form (I recommend CultureInfo.InvariantCulture).

    Second, to make the cut-and-past job of inserting the static logger declaration, I use MethodBase.GetCurrentMethod().DeclaringType to yield the type of the static-constructor being run (instead of that copy-paste-error-prone typeof(Bar) used in the example above.

    Third, with things built as you have above, the TRACE constant must be present when compiling. This makes it impossible to decide after deployment to turn on tracing, which is NOT a situation I want to be in… if there is something REALLY performance sensitive, that’s fine, but not for the general case.

    Other than those issues, I like the idea of _slightly_ abstracting away, but I think we would all be better served if these sorts of changes were made to log4net itself.

    Comment by Marc Brooks — November 4, 2006 @ 2:32 am

  2. Hi Marc,

    thanks for the feedback.

    Regarding the format members of the ILog interface: I saw those members documented in the online SDK help (I almost thought they would spoil my post ;-)), yet this part of the documentation is not in sync with the download I got (log4net-1.2.0-beta8). I know that there are later releases but according to the log4net download page they are “incubating releases” and as such “[...] these releases are not officially endorsed by the ASF.”
    Even if I take those methods into account, there is the point that the documentation doesn’t mention them and the fact that the ILog interface cannot (and should not try to) be extended to cover every thinkable overload, be it for type safety or efficiency.

    Regarding the static logger: Cut-and-paste errors were not my point (with code snippets or tools like resharper one could even avoid these errors without refering to reflection). My point was to avoid to have a logger instance (which has to be declared, initialized and still be checked for null) and instead utilze static methods.

    Regarding the TRACE constant: Yes you are right, TRACE has to be set. But this is exactly what I expect, just as the .NET documentation states: “By default, all configurations for a project define TRACE.” This especially includes release builds.

    Regarding contribution: I agree that we all should contribute to things we take advantage of. But there are other things to consider. One point of this little helper class was to be tailored for type safety and other things which depend on the actual application, not on log4net. Next, I think I am contributing with this post – perhaps not code but at least something to think about. Lastly, I don’t know the state of discussions and arguments within the log4net team and I know nothing about their design decissions. You don’t simply show up and paste some code, you have to participate in the whole process to do it right. And to be frank, I ain’t got the time to do this.

    Regards,
    AJ.NET

    Comment by ajdotnet — November 5, 2006 @ 6:59 pm

  3. I really like the simplicity of the wrapper class.

    For performance, however, calling LogManager.GetLogger for EVERY call to the DebugFormat message seems costly. By allocating the log object in a constructor, I can make a single call to LogManager.GetLogger, then use the log4net object multiple times without needing to pay the price of the context object lookup.

    public class LogHelper
    {
    [Conditional(“TRACE”)]
    public static DebugFormat(object context, string format, params object[] args)
    {
    ILog log = LogManager.GetLogger(context.GetType()); // <— Isn’t this going to hurt performance?
    if ((log==null)) || !log.IsDebugEnabled)
    return;
    string msg= string.Format(format, args);
    log.Debug(msg);
    }

    […]
    }

    Comment by Doug — September 5, 2007 @ 9:47 pm

  4. @Doug:
    // <— Isn’t this going to hurt performance?
    I don’t know. Is it? Seriously, I didn’t measure it and it never showed up in my profiling sessions. Perhaps log4net already maintains loggers in its own cache? If not it’s probably one of the easier exercises to cache the loggers (either in a dictionary, or for regular cleanup in the ASP.NET cache).

    Comment by ajdotnet — September 6, 2007 @ 7:20 am

  5. Log4net does not cache, and even if it did, there is a cache lookup overhead that you don’t have with a statically allocated logger.

    And if you always use the same name, ie: LOGGER, then it is a no brainer, really.

    Comment by Me — November 26, 2007 @ 7:24 am


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

The Shocking Blue Green Theme. Create a free website or blog at WordPress.com.

Follow

Get every new post delivered to your Inbox.

Join 244 other followers

%d bloggers like this: