Nov
7

Performance of logging system

alkampfer on November 7th, 2008

When you insert a logging system into your application you should do some preliminary test for performance issue. The most important thing is that logging infrastructure should not introduce too much overhead when the log is disabled. With log4net you have different way to handle the log, suppose you have a logger and the DEBUG level is disabled; you can use one of these three form

log1.Debug("TEST");
if (log1.IsDebugEnabled) log1.Debug("TEST");

Boolean isDebugEnabled = log1.IsDebugEnabled;
if (isDebugEnabled) log1.Debug("TEST");

The first version rely on the fact that log4net infrastructure internally checks if debug is enabled so you can call Debug function directly. The second technique is to check if log1.IsDebugEnabled before calling log1.Debug(), and the third stores the IsDebugEnabled in a local variable to check that variable instead of calling IsDebugEnabled each time. If you do one million log calls you will obtain these rough measurements in milliseconds.

log1.Debug("TEST") = 828.125
if (log1.IsDebugEnabled) log1.Debug("TEST") = 750
if (isDebugEnabled)  log1.Debug("TEST") = 31.25

Thus solution 1 and 2 are quite similar in performances, while the third version is obviously the winner because it has not to call the log1.IsDebugEnabled at each run.

Now suppose that the messages is not a constant string but it has to be build

for (Int32 I = 0; I < iterations; ++I)
{
    log1.Debug("TEST" + I.ToString() + "other");
}

In this situation the first test is important

log1.Debug("TEST" + I.ToString() + "other") = 2968.75
if (log1.IsDebugEnabled) log1.Debug("TEST" + I.ToString() + "other") = 75
if (isDebugEnabled)  log1.Debug("TEST" + I.ToString() + "other") = 31.25

The second and third results have the same timing as before, the log is disabled so both conditions evaluates to false as before. The important fact is that the first technique is much more slower, this because even if the debug level is not enable, you have to pay the time to do string concatenation to create the message to send to log.Debug function.

The conclusion is: always check if the log is enabled. Moreover do not forget to use log4net compiled in release mode to production code, the above timing with release version of log4net are the followings. 

log1.Debug("TEST") = 359.375
if (log1.IsDebugEnabled) log1.Debug("TEST") = 250
if (isDebugEnabled)  log1.Debug("TEST") = 0
log1.Debug("TEST" + I.ToString() + "other") = 2296.875
if (log1.IsDebugEnabled) log1.Debug("TEST" + I.ToString() + "other") = 250
if (isDebugEnabled)  log1.Debug("TEST" + I.ToString() + "other") = 15.625

As you can expect, the release version have really better performance.

Alk.

Tags:

DotNetKicks Image
kick it on DotNetKicks.com

.NET framework, Tools and library
Subscribe
Delicious
digg
technorati
google

2 Responses to “Performance of logging system”

  1. Jeremy Gray
    November 7th, 2008 at 11:25 am

    That is a really interesting result, particularly because the log4net documentation goes out of its way to talk about how cheap the Is*Enabled calls are (supposed to be) ! I’ll definitely have to factor that change into my code, seeing as we conditionally generate debug-level events very frequently.

  2. alkampfer
    November 14th, 2008 at 11:56 am

    I should also make a precisation, Log4Net has also an inner DebugFormat that can be used when you want to log something with string composition.

    log1.DebugFormat(”TEST {0} other” , I);

    In this way performance loss is not so much here is the result.

    log1.Debug(“TEST 406.25 other”) = 406.25
    if (log1.IsDebugEnabled) log1.Debug(“TEST” + I.ToString() + “other”) = 250
    if (isDebugEnabled) log1.Debug(“TEST” + I.ToString() + “other”) = 31.25

    You still can do a better job checking if the log level is enable before calling the logger.

    alk.