Hi,

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 missed 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?