Log4j: is it synchronized for multithreaded calls?

Question

We are running into an interesting issue that we noticed while doing stress testing of our system. We are using log4j (in JBOSS) very heavily for our logging. Here is a naive example of some logging we ave

void someFunction()
{
Log.info("entered some function");
...

Log.info("existed some function");
}

Now the interesting thing we noticed is that if we launch 100 threads against this function; the Log.info() calls is blocking per thread.. meaning thread 2 is waiting for thread1 to finish the "Log.info" call. In case of Thread 100; it ends up waiting quite a long time.. We are using a native file logger.

Is this a known issue?

Ok thanks. Just wanted to make sure. I was going though the source code of `Logger` and found that there is indeed a `synchronized` section there. — Tudor, Feb 21 '12 at 22:43

score 15 · Answer 1 · answered Feb 18 '12 at 18:36

15

Log4J has to be synchronized, otherwise you would see interleaved and garbled log messages in your file. But at least in Logback only appenders are synchronized, not the whole logging message (so computing effective log level, log message, etc. is multi-threaded).

However even if synchronization was removed, I/O would be the bottleneck since it is inherently single-threaded. Thus consider reducing the amount of logging, since it is the file access that is slow, not Log4J.

You may also be interested in AsyncAppender to queue logging messages in a single, different thread.

answered Feb 18 '12 at 18:36

Tomasz Nurkiewicz

334,321
69
703
674

3

+1 - one thing I think is worth mentioning is the trade-off with async approaches; you're not guaranteed all logging has made it to disk in the case of a process or system crash – Brian Roach Feb 18 '12 at 18:54
I'm not sure I understand the AsyncAppender. Isn't the logging actually 'asynchornous'.. meaning happening in a separate thread? Meaning in my example above; when I call "Log.Info("abc"); it doesn't actually write out into the file right away.. it seems to be delayed? – shergill Feb 22 '12 at 05:33
@shegill, yes it is delayed. It is buffered in the AsyncAppender before it is sent to the delegatee appenders. This is the reason for Brian's warning about losing log messages in the event of a system crash; you run the same danger if you are not having your appenders flush to disk after every log message. – Victor Apr 03 '13 at 14:49
1

@Tomasz Nurkiewicz "Log4J has to be synchronized, otherwise you would see interleaved and garbled log messages in your file". This is exactly what I am seeing in a local multithreaded application. Both with and without using the AsyncAppender. – ryoung Jun 19 '15 at 20:23

score 2 · Answer 2 · edited May 23 '17 at 12:34

What you might want is asynchronous logging, see this article on how to achieve that:

Asynchronous logging with log4j

Also, consider using the right log levels. The entered... and exi(s)ted... statements should typically be logged at TRACE level, which might be handy when debugging (then set configure log4j to log at TRACE level as well). In a production setting you might want to tell log4j to log only from level INFO or DEBUG, thus avoiding unnecessary log actions.

See also this question on the performance of log4j:

log4j performance

score 2 · Answer 3 · edited May 23 '17 at 10:29

Yes, log4j uses multithread syncronyzation. And not perfectly, sometimes.

We had experienced some performance degradation caused by contention for log4j locks and even deadlocks with use of complex toString() method.

See https://issues.apache.org/bugzilla/show_bug.cgi?id=24159 and https://issues.apache.org/bugzilla/show_bug.cgi?id=41214#c38, for example.

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

I guess this is one of the reasons of logback existence and switch to custom logmanager since JBoss AS 6.

Tudor · Answer 4 · 2012-02-18T23:53:52.767

Others have already suggested you alternatives, I've been digging through the source code and indeed there is a synchronized section:

public void info(Object message) {
    if(repository.isDisabled(Level.INFO_INT))
       return;
    if(Level.INFO.isGreaterOrEqual(this.getEffectiveLevel()))
       forcedLog(FQCN, Level.INFO, message, null);
}

...

protected void forcedLog(String fqcn, Priority level, Object message, Throwable t) {
    callAppenders(new LoggingEvent(fqcn, this, level, message, t));
}

...

public void callAppenders(LoggingEvent event) {
    int writes = 0;

    for(Category c = this; c != null; c=c.parent) {
        // Protected against simultaneous call to addAppender, removeAppender,...
        synchronized(c) {
            if(c.aai != null) {
                writes += c.aai.appendLoopOnAppenders(event);
            }
            if(!c.additive) {
                break;
            }
        }
    }

    if(writes == 0) {
        repository.emitNoAppenderWarning(this);
    }
}

score -4 · Answer 5 · answered Oct 21 '12 at 00:49

Agree with previous answers. One of the first performance improvement steps in any application is to reduce the log level and have it dump less logs. Application developers should be diligent in using the right logging levels. Logging has a huge impact on performance because of I/O as well as synchronization especially when logger objects are static and shared among various threads.

Log4j: is it synchronized for multithreaded calls?

5 Answers5