log4j performance

Question

I'm developing a web app, and I'd like to log some information to help me improve and observe the app. (I'm using Tomcat6)

First I thought I would use StringBuilders, append the logs to them and a task would persist them into the database like every 2 minutes. Because I was worried about the out-of-the-box logging system's performance. Then I made some test. Especially with log4j.

Here is my code:

Main.java

public static void main(String[] args) {
  Thread[] threads = new Thread[LoggerThread.threadsNumber];

  for(int i = 0; i < LoggerThread.threadsNumber; ++i){
   threads[i] = new Thread(new LoggerThread("name - " + i));
  }
  LoggerThread.startTimestamp = System.currentTimeMillis();

  for(int i = 0; i < LoggerThread.threadsNumber; ++i){
   threads[i].start();
  }

LoggerThread.java

public class LoggerThread implements Runnable{
 public static int threadsNumber = 10;
 public static long startTimestamp;
 private static int counter = 0;
 private String name;

 public LoggerThread(String name) {
  this.name = name;
 }
 private Logger log = Logger.getLogger(this.getClass());

 @Override
 public void run() {
  for(int i=0; i<10000; ++i){
   log.info(name + ": " + i);

   if(i == 9999){
    int c = increaseCounter();

    if(c == threadsNumber){
     System.out.println("Elapsed time: " + 
       (System.currentTimeMillis() - startTimestamp));
    }
   }

  }
 }

 private synchronized int increaseCounter(){
  return ++counter;
 }

}
     }

log4j.properties

log4j.logger.main.LoggerThread=debug, f
log4j.appender.f=org.apache.log4j.RollingFileAppender
log4j.appender.f.layout=org.apache.log4j.PatternLayout
log4j.appender.f.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n
log4j.appender.f.File=c:/logs/logging.log
log4j.appender.f.MaxFileSize=15000KB
log4j.appender.f.MaxBackupIndex=50

I think this is a very common configuration for log4j. First I used log4j 1.2.14 then I realized there was a newer version, so I switched to 1.2.16

Here are the figures (all in millisec)

LoggerThread.threadsNumber = 10

1.2.14: 4235, 4267, 4328, 4282
1.2.16: 2780, 2781, 2797, 2781

LoggerThread.threadsNumber = 100

1.2.14: 41312, 41014, 42251
1.2.16: 25606, 25729, 25922

I think this is very fast. Don't forget that: in every cycle the run method not just log into the file, it has to concatenate strings (name + ": " + i), and check an if test (i == 9999).

When threadsNumber is 10, there are 100.000 loggings and if tests and concatenations. When it is 100, there are 1.000.000 loggings and if tests and concatenations. (I've read somewhere JVM uses StringBuilder's append for concatenation, not simple concatenation).

Did I miss something? Am I doing something wrong? Did I forget any factor that could decrease the performance? If these figures are correct I think I don't have to worry about log4j's performance even if I heavily log, do I?

I've read that: "The typical cost of actually logging is about 100 to 300 microseconds." Is it correct? (log4J manual)

Answer 1

If performance is a concern, be sure to pay special attention to the pattern layout documentation and avoid expensive conversion characters such as C, F, L, and M. These require shenanigans to retrieve this info.

In place of C, use c and appropriately name your Logger objects when they are created. This means you can't inherit loggers from parent classes, but the inconvenience of redefining the logger is worth the increase to performance. F, L, and M don't have easy replacements for their functionality, but well worded log messages should be really easy to find in your source, so the need to specify the exact method, file, and line is diminished.

Finally, avoid dynamic string concatenation in your log messages. When it is necessary to use concatenation, be sure to wrap the creation of that logging string in the appropriate checker method.

private final static Logger LOG = Logger.get(MyClass.class);
...
void someMethod() {
    if (LOG.isDebugEnabled()) {
        LOG.debug("some really expensive string concatenation: " + someInstanceVariable + " a bunch of other text!");
    }
}

The isDebugEnabled() always runs in constant time. LOG.debug() itself essentially does a isDebugEnabled() check at the beginning, but the string passed as a parameter must be fully built before that check can happen, causing an unnecessary delay when debug level is turned off.