Why call IsDebugEnabled in log4net?

Question

I'm curious as to why I see people write log4net logging code like the following:

if (_logger.IsDebugEnabled)
{
    _logger.Debug("Some debug text");
}

I've gone through the disassembly for log4net, and calling Debug makes another call to the same code to see if it's enabled before actually logging, so the IsDebugEnabled call is unnecessary and actually is duplicated code.

Is there a reason people do this? Maybe an old pattern that used to be necessary in older versions but isn't anymore? Or could there be a legitimate reason for it? Or maybe people just don't know that they don't need to do it?

This same behavior is there for the other levels (Info, Error, Warn, Finest, etc.) as well.

Answer 1

This pattern is used purely for performance reasons, specifically when logging to a certain logging level will be skipped because the logging level is not currently enabled. It is a lot cheaper to check the boolean IsDebugEnabled flag and skip the method call than it is to call the Debug method with arguments and the method to return without logging.

If you were to call the Debug method and pass in a message containing something that was costly to create, you could skip the creation of the message altogether by first checking the enabled flag.

All that being said, unless you are making log messages that are very expensive to make (eg. something like a stack trace) or you are logging in a tight loop, it is unlikely that it will be a bottleneck for your code.

Answer 2

The message could be expensive to build. Wrapping it in the if statement ensures it is only created when necessary.

Another pattern that addresses this issue is:

_logger.Debug(() => "Some expensive text");

I don't know if log4net supports anything like that, though.