/dev/blog

Ever seen duplicate lines in your log4j output? Maybe something like this:

2010-06-28 21:56:11,743 [main] INFO  org.quartz.impl.StdSchedulerFactory - Quartz scheduler version: 1.8.1
2010-06-28 21:56:11,743 [main] INFO  org.quartz.impl.StdSchedulerFactory - Quartz scheduler version: 1.8.1
2010-06-28 21:56:11,750 [main] INFO  org.quartz.core.QuartzScheduler - Scheduler MyScheduler_$_1 started.
2010-06-28 21:56:11,750 [main] INFO  org.quartz.core.QuartzScheduler - Scheduler MyScheduler_$_1 started.

Well, the obvious cause is probably duplicate loggers your log4j configuration:

log4j.rootLogger=INFO, DefaultConsoleAppender
log4j.logger.org.quartz=DEBUG, DefaultConsoleAppender

As the properties are inherited from the root logger, this is telling log4j that all quartz-classes should send their log to the DefaultConsoleAppender (which the root logger is doing anyway). So we simply have to remove the appender from the second logger definition:

log4j.rootLogger=INFO, DefaultConsoleAppender
log4j.logger.org.quartz=DEBUG

So watch your inherited log levels and appenders in your log4j configuration!

If anyone knows, why these duplicate lines appear from time to time in heavily multi-threaded environments (although log4j claims to be thread-safe) despite correct property files, please drop me a mail or leave a comment.

Log4J is the current de facto standard not only in open source development. It claims to be fast and flexible: speed first, flexibility second. But there are some pitfalls when it comes to the crunch.

The costs of a log request consists of a method invocation and an integer comparison. This is typically about 1-20ns (depending on your processor) per call. However, this does not include the “hidden” costs of parameter construction.
A simple example:

logger.debug("Value: " + x*y);

Regardless of whether the message will actually be logged or not, the parameter construction will cause additional costs. These costs of parameter construction can be quite high and depend on the size of the parameters involved.

To avoid the parameter construction costs:

      if(logger.isDebugEnabled() {
        logger.debug("Value: " + x*y);
      }
  

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.

So if speed is a real issue, you should double-check your logging statements for “hidden” costs.

Resources:
http://logging.apache.org/log4j/1.2/manual.html