How fast is a log4net logging method (Debug, Info, etc)?

Question

I'm a big fan of log4net, but recently, some (in my department) have questioned its inclusion in our projects because of the seemingly heaviness of each logging method. I would argue that there are better techniques than others, but that's another question.

I'm curious to know, what is the typical impact of a log4net DebugFormat-type call on your applications. I'm going to leave out variables like number of log statements per lines of code, etc, because I'm just looking for anything that you've seen in the real world.

And, I am aware of the simple technique of adding a guard clause to long evaluation statements eg:

if (log.IsDebug)
{
  log.DebugFormat(...);
}

So, let's exclude that from consideration for now.

Answer 1

I am not familiar with log4net, or log.DebugFormat(...).

But the cost of logging is really in two areas.

The first is the logging call, and the second is the actual persisting of the log information.

The guards help reduce the logging call to a minimum when the logging is not actually necessary. It tends to be very fast, since it's little more than a method call and a comparison of two scalars.

However, when you don't use guards, the cost may well become the price of creating the actual logging arguments.

For example, in log4j, this was a common idiom:

log.debug("Runtime error. Order #" + order.getOrderNo() + " is not posted.");

Here, the cost is the actual evaluation of the string expression making the message. This is because regardless of the logging level, that expression, and the resulting string are created. Imagine if instead you had something like:

log.debug("Something wrong with this list: " + longListOfData);

That could create a large and expensive string variable that, if the log level wasn't set for DEBUG, would simply be wasted.

The guards:

if (log.isDebug()) {
    log.debug(...);
}

Eliminate that problem, since the isDebug call is cheap, especially compared to the actual creation of the argument.

In my code, I have written a wrapper for logging, and I can create logs like this:

log.debug("Runtime error. Order # {0} is not posted.", order.getOrderNo());

This is a nice compromise. This relies on Java varargs, and my code checks the logging level, and then formats the message appropriately. This is almost as fast as the guards, but much cleaner to write.

Now, log.DebugFormat may well do a similar thing, that I don't know.

On top of this, of course, is the actual cost of logging (to the screen, to a file, to a socket, etc.). But that's just a cost you need to accept. My best practice for that, when practical, is to route the actual log messages to a queue, which is then reaped and output to the proper channel using a separate thread. This, at least, helps keep the logging out of line with the main computing, but it has expenses and complexity of its own.

Answer 2

I know this is an old thread, but how about using an approach that avoids filling the code with if statements based on log level, such as this one: http://www.beefycode.com/post/Extension-Methods-for-Deferred-Message-Formatting-in-Log4Net.aspx

Using lambda expression to build the message, you can avoid even evaluating it entirely.

Answer 3

The log4net FAQ has an answer to this, although not to the level of detail you are looking for.

In summary: use those guard clauses.

Answer 4

Just Giving Will Hartung's answer a .NET perspective :)

DebugFormat code is:

if (IsDebugEnabled)
{
    Logger.Log(ThisDeclaringType, m_levelDebug, new SystemStringFormat(CultureInfo.InvariantCulture, format, args), null);
}

Basically it is the same so it's my believe that when you use DebugFormat you don't need to use the guard clause (You may still have a small overhead but I think it's small enough to be ignored)

would have left a comment but I don't have enough reputation :/