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)
_______________________________________________
Logback-user mailing list
[email protected]
http://qos.ch/mailman/listinfo/logback-user
