Hello, based on the old topic archived here for example: http://old.nabble.com/logback-performance-clarification-td9390741.html I performed set of similar tests with debug level actually enabled to see how does logback perform when actually logging. - I noticed slightly worse (than log4j) logback performance in most cases, especially on my Windows machine - I was also interested in the effect of immediateFlush option which was giving us noticable performance improvement with log4j, but was removed from logback as of 0.9.19 (http://logback.qos.ch/manual/appenders.html). Here I noticed that immediateFlush was still giving something (I had to test on logback 0.9.18 in order to compare that). Sad that it was removed. - I've also done some more tests with info level and logback parametrized debug call combined with isDebugEnabled and this one shows typically better performance than plain parametrized debug call as well as classic debug call with isDebugLevel. The main question is - why was immediateFlush removed when it really gives some improvement? Here are some results (all tests performed on Java 1.5 due to its use by the application server we're running at): Windows: log4j 1.2.16, logback 0.9.28 immediateFlush true: ############################################### Log4j direct debug call: 13516 Log4j tested (isDebugEnabled) debug call: 13595 Logback direct debug call: 15593 Logback tested (isDebugEnabled) debug call: 17273 Logback parametrized debug call: 19011 ############################################### Windows: log4j 1.2.16, logback 0.9.18 immediateFlush true: ############################################### Log4j direct debug call: 13421 Log4j tested (isDebugEnabled) debug call: 13240 Logback direct debug call: 15562 Logback tested (isDebugEnabled) debug call: 17112 Logback parametrized debug call: 17981 ############################################### Windows: log4j 1.2.16, logback 0.9.18 immediateFlush false: ############################################### Log4j direct debug call: 6562 Log4j tested (isDebugEnabled) debug call: 6608 Logback direct debug call: 6137 Logback tested (isDebugEnabled) debug call: 7418 Logback parametrized debug call: 8273 ############################################### HP-UX: log4j 1.2.16, logback 0.9.28 immediateFlush true: ############################################### Log4j direct debug call: 17385 Log4j tested (isDebugEnabled) debug call: 17411 Logback direct debug call: 17351 Logback tested (isDebugEnabled) debug call: 17315 Logback parametrized debug call: 17677 ############################################### HP-UX: log4j 1.2.16, logback 0.9.18 immediateFlush true: ############################################### Log4j direct debug call: 17522 Log4j tested (isDebugEnabled) debug call: 17688 Logback direct debug call: 17418 Logback tested (isDebugEnabled) debug call: 17525 Logback parametrized debug call: 17071 ############################################### HP-UX machine: log4j 1.2.16, logback 0.9.18 immediateFlush false: ############################################### Log4j direct debug call: 9936 Log4j tested (isDebugEnabled) debug call: 10869 Logback direct debug call: 9900 Logback tested (isDebugEnabled) debug call: 9907 Logback parametrized debug call: 10346 ############################################### code used for testing ---------------------------------------------------------------------------------------------- package perfTest.ch.qos.logback; import org.slf4j.Logger; import org.slf4j.LoggerFactory; public class PerformanceComparator { static Logger logbacklogger = LoggerFactory.getLogger(PerformanceComparator.class); static org.apache.log4j.Logger log4jlogger = org.apache.log4j.Logger.getLogger(PerformanceComparator.class); // How many times should we try to log: static int loop = 1000000; public static void main(String[] args) throws InterruptedException { initConfig(); // Let's run once for Just In Time compiler log4jDirectDebugCall(); log4jTestedDebugCall(); logbackDirectDebugCall(); logbackTestedDebugCall(); logbackParametrizedDebugCall(); // let's run the tests and display the results: long result1 = log4jDirectDebugCall(); long result2 = log4jTestedDebugCall(); long result3 = logbackDirectDebugCall(); long result4 = logbackTestedDebugCall(); long result5 = logbackParametrizedDebugCall(); System.out.println("###############################################"); System.out.println("Log4j direct debug call: " + result1); System.out.println("Log4j tested (isDebugEnabled) debug call: " + result2); System.out.println("Logback direct debug call: " + result3); System.out.println("Logback tested (isDebugEnabled) debug call: " + result4); System.out.println("Logback parametrized debug call: " + result5); System.out.println("###############################################"); } private static long log4jDirectDebugCall() { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { log4jlogger.debug("SEE IF THIS IS LOGGED " + j + "."); } return (System.nanoTime() - start) / loop; } private static long log4jTestedDebugCall() { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { if (log4jlogger.isDebugEnabled()) { log4jlogger.debug("SEE IF THIS IS LOGGED " + j + "."); } } return (System.nanoTime() - start) / loop; } private static long logbackDirectDebugCall() { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { logbacklogger.debug("SEE IF THIS IS LOGGED " + j + "."); } return (System.nanoTime() - start) / loop; } private static long logbackTestedDebugCall() { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { if (logbacklogger.isDebugEnabled()) logbacklogger.debug("SEE IF THIS IS LOGGED " + j + "."); } return (System.nanoTime() - start) / loop; } private static long logbackParametrizedDebugCall() { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { //if (logbacklogger.isDebugEnabled()) //test logbacklogger.debug("SEE IF THIS IS LOGGED {}.", j); } return (System.nanoTime() - start) / loop; } private static void initConfig() { org.apache.log4j.Logger log4jRoot = org.apache.log4j.Logger.getRootLogger(); //log4jRoot.setLevel(org.apache.log4j.Level.INFO); ch.qos.logback.classic.Logger lbRoot = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger("ROOT"); //lbRoot.setLevel(ch.qos.logback.classic.Level.INFO); // create the loggers org.apache.log4j.Logger.getLogger("perfTest"); org.apache.log4j.Logger.getLogger("perfTest.ch"); org.apache.log4j.Logger.getLogger("perfTest.ch.qos"); org.apache.log4j.Logger.getLogger("perfTest.ch.qos.logback"); LoggerFactory.getLogger("perfTest"); LoggerFactory.getLogger("perfTest.ch"); LoggerFactory.getLogger("perfTest.ch.qos"); LoggerFactory.getLogger("perfTest.ch.qos.logback"); } } ---------------------------------------------------------------------------------------------- log4j configuration ---------------------------------------------------------------------------------------------- <?xml version="1.0" encoding="UTF-8"?> <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd"> <log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="false"> <appender name="TestLogfile" class="org.apache.log4j.RollingFileAppender"> <param name="File" value="testlog4j.log"/> <param name="MaxFileSize" value="1000KB"/> <param name="maxBackupIndex" value="1"/> <param name="immediateFlush" value="true"/> <layout class="org.apache.log4j.PatternLayout"> <param name="ConversionPattern" value="%d{ISO8601} %5p [%t] %c{1} %X{transactionId} - %m%n"/> </layout> </appender> <root> <level value="debug"/> <appender-ref ref="TestLogfile"/> </root> </log4j:configuration> ---------------------------------------------------------------------------------------------- logback 0.9.28 configuration ---------------------------------------------------------------------------------------------- <configuration> <appender name="TestLogfile" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>testlogback.log</file> <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy"> <fileNamePattern>testlogback.log.%i</fileNamePattern> <minIndex>1</minIndex> <maxIndex>1</maxIndex> </rollingPolicy> <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy"> <maxFileSize>1000KB</maxFileSize> </triggeringPolicy> <encoder> <Pattern>%d{ISO8601} %5p [%t] %c{0} %X{transactionId} - %m%n</Pattern> <charset>UTF-8</charset> </encoder> </appender> <root> <level value="debug" /> <appender-ref ref="TestLogfile" /> </root> </configuration> ---------------------------------------------------------------------------------------------- logback 0.9.18 configuration ---------------------------------------------------------------------------------------------- <configuration> <appender name="TestLogfile" class="ch.qos.logback.core.rolling.RollingFileAppender"> <File>testlogback.log</File> <ImmediateFlush>true</ImmediateFlush> <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy"> <FileNamePattern>testlogback.log.%i</FileNamePattern> <MinIndex>1</MinIndex> <MaxIndex>1</MaxIndex> </rollingPolicy> <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy"> <MaxFileSize>1000KB</MaxFileSize> </triggeringPolicy> <Encoding>UTF-8</Encoding> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern>%d{ISO8601} %5p [%t] %c{0} %X{transactionId} - %m%n</Pattern> </layout> </appender> <root> <level value="debug" /> <appender-ref ref="TestLogfile" /> </root> </configuration> ----------------------------------------------------------------------------------------------