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

If you are using guards as you mentioned, then performance should not be an issue when you have production code logging only errors. You're only turning on verbose logging when there is a problem that needs investigating, right?

Answer 2

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

[1]: http://logging.apache.org/log4net/release/faq.html#What is the fastest way of (not) logging?

In summary: use those guard clauses.

Answer 3

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.