log4j performance

问题:

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)

回答1:

Yes, Log4J is known to be fast, due to the conscious effort of its implementors. See also the section "Performance" at the end of this introduction to Log4J.

回答2:

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.

回答3:

I don't have to worry about log4j's performance even if I heavily log

Exactly. Do not optimize until your profiling results tell you to. There are cases, when logging performance is a bottleneck, but you need first to hit that case, then optimize for it.

回答4:

the bottle neck should be the hard disk. your test shows roughly 1MB/s disk write speed, which is quite poor actually.

回答5:

Make sure you have a proper logging strategy. That means make sure you define what to log and have it separated into debug, trace, info, warning and error as well some others if you need them. Also make sure you give the ability to switch it on and off to enact performance/debugging as needed.

Logging can have a significant impact on a heavily used site/app, Also logging too much gives you more information than you can sort through. Logging sometimes is the only post-incident debugging tool you have so make sure you make it count.

回答6:

If performance is really a concern have a look for slf4j: http://www.slf4j.org/manual.html

With their placeholder approach they are faster than log4j when you disabled logging those messages, because in log4j the string concatenation takes places independently the message is really needed. Slf4j only replaces the placeholder if this message will be really logged.

But you can do something like this in log4j:

if(l.isDebugEnabled()) l.debug("log entry: " + 7);

But i think it's a lot of boilerplate-code so i am using slf4j

回答7:

It must be noted that log4j suffers from numerous locking pains under heavy concurrent use.

More details and some workaround in my another answer: Production settings file for log4j?