what's log4j actually doing when we turn on or off some log places?

Question

We know we can config log4j to turn off log on specific places (class or package in Java) via its properties/configuration file. My questions are followed:

1. what's log4j actually doing for those flags?
2. is the log statement in log4j still called but just not being written to file or console because of that flag? so still have performance impact?
3. is it like #ifdef in C++ which take effect at compile time then can limit the performance impact?

thanks,

Answer 1

Yes, the log statements will still be executed. This is why it's a good pattern to check the log level first: something like

if (log.isInfoEnabled()) {
    log.info("My big long info string: " + someMessage);
}

This is to keep from reallocating space for the info String when the log level does not support INFO statements.

It's not anything like #ifdef - #ifdef is a compiler directive, whereas Log4J configurations are processed at runtime.

Edit: I hate getting downmodded due to ignorance, so here is one article backing up my answer.

From http://surguy.net/articles/removing-log-messages.xml:

In Log4J, if you log a message at DEBUG level, and the current Appender is set to only log messages of INFO level and above, then the message will not be displayed. The performance penalty for calling the log method itself is minimal - a few nanoseconds. However, it may take longer to evaluate the arguments to the log method. For example:

logger.debug("The large object is "+largeObject.toString());

Evaluating largeObject.toString() may be slow, and it is evaluated before the call to the logger, so the logger cannot prevent it being evaluated, even though it will not be used.

Edit 2: from the log4j manual itself (http://logging.apache.org/log4j/1.2/manual.html):

The user should be aware of the following performance issues.

1. Logging performance when logging is turned off. When logging is turned off entirely or just for a set of levels, the cost of a log request consists of a method invocation plus an integer comparison. On a 233 MHz Pentium II machine this cost is typically in the 5 to 50 nanosecond range.

   However, The method invocation involves the "hidden" cost of parameter construction.

   For example, for some logger cat, writing,

    logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));
   

   incurs the cost of constructing the message parameter, i.e. converting both integer i and entry[i] to a String, and concatenating intermediate strings, regardless of whether the message will be logged or not. This cost of parameter construction can be quite high and it depends on the size of the parameters involved.

   To avoid the parameter construction cost write:

   if(logger.isDebugEnabled() {
     logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));
   }
   

   This will not incur the cost of parameter construction if debugging is disabled. On the other hand, if the logger is debug-enabled, it will incur twice the cost of evaluating whether the logger is enabled or not: once in debugEnabled and once in debug. This is an insignificant overhead because evaluating a logger takes about 1% of the time it takes to actually log.

Answer 2

I ran a simple benchmark to test.

    for (int j = 0; j < 5; j++) {
        long t1 = System.nanoTime() / 1000000;
        int iterations = 1000000;
        for (int i = 0; i < iterations; i++) {
            int test = i % 10;
            log.debug("Test " + i + " has value " + test);
        }
        long t2 = System.nanoTime() / 1000000;
        log.info("elapsed time: " + (t2 - t1));

        long t3 = System.nanoTime() / 1000000;
        for (int i = 0; i < iterations; i++) {
            int test = i % 10;
            if (log.isDebugEnabled()) {
                log.debug("Test " + i + " has value " + test);
            }
        }
        long t4 = System.nanoTime() / 1000000;
        log.info("elapsed time 2: " + (t4 - t3));
    }

elapsed time: 539
elapsed time 2: 17
elapsed time: 450
elapsed time 2: 18
elapsed time: 454
elapsed time 2: 19
elapsed time: 454
elapsed time 2: 17
elapsed time: 450
elapsed time 2: 19

With 1.6.0_18, which surprised me as I would have thought the inlining would have prevented this. Maybe Java 7 with escape analysis will.

However I still wouldn't wrap debug statements in an if clause unless time improvements of the order of half a microsecond get to be important!