
For multithreaded case I slightly modified the test to run with 100 threads, each producing 10000 log events. The profile data shows high lock contention in method ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(java.lang.Object) (same as I mentioned in my previous mail) and thread dumps always reveal one runnable thread doing some writing while all other threads are waiting for it. Run times are typically 2-3 times worse than with log4j with immediateFlush=false (6.3-9s vs. 13-20s). So some sort of write batching/buffering really helps in case of heavy activity. "Thread-53" prio=7 tid=00478fa0 nid=67 lwp_id=4143914 runnable [32500000..32500ad0] at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:260) at ch.qos.logback.core.recovery.ResilientOutputStreamBase.write(ResilientOutputStreamBase.java:52) at java.io.OutputStream.write(OutputStream.java:58) at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:103) at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:193) at ch.qos.logback.core.FileAppender.writeOut(FileAppender.java:220) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:217) - locked <3a84d188> (a java.lang.Object) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:108) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:64) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:285) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:272) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:473) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:427) at ch.qos.logback.classic.Logger.debug(Logger.java:534) at perfTest.ch.qos.logback.PerformanceComparator3.logbackDirectDebugCall(PerformanceComparator3.java:63) at perfTest.ch.qos.logback.PerformanceComparator3.access$000(PerformanceComparator3.java:6) at perfTest.ch.qos.logback.PerformanceComparator3$1.run(PerformanceComparator3.java:33) at java.lang.Thread.run(Thread.java:595) "Thread-54" prio=7 tid=00479190 nid=68 lwp_id=4143915 waiting for monitor entry [32440000..32440b50] at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:216) - waiting to lock <3a84d188> (a java.lang.Object) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:108) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:64) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:285) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:272) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:473) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:427) at ch.qos.logback.classic.Logger.debug(Logger.java:534) at perfTest.ch.qos.logback.PerformanceComparator3.logbackDirectDebugCall(PerformanceComparator3.java:63) at perfTest.ch.qos.logback.PerformanceComparator3.access$000(PerformanceComparator3.java:6) at perfTest.ch.qos.logback.PerformanceComparator3$1.run(PerformanceComparator3.java:33) at java.lang.Thread.run(Thread.java:595)