[logback-user] log4j performance comparison

[hostalp at post.cz]

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)