[logback-user] log4j performance comparison

[Ceki Gulcu]

On 18.03.2011 19:10, hostalp at post.cz wrote:
> 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):
>

Hello hostalp,

The test you mention was designed to measure the performance of disabled 
log statements. For your test case, you might as well ignore the 
difference between the direct/isDebugEnabled/parametrized versions.

For example, I have simplified the main method to:

  public static void main(String[] args) throws InterruptedException {
      // not necessary
      //initConfig();

      // Let's run once for Just In Time compiler
      log4jDirectDebugCall();
      logbackDirectDebugCall();

      // let's run the tests and display the results:
      long result1 = log4jDirectDebugCall();
      long result3 = logbackDirectDebugCall();

      System.out.println("##########################################");
      System.out.println("Smaller is better!");
      System.out.println("Log4j direct debug call: " + result1);
      System.out.println("Logback direct debug call: " + result3);
    }

You should begin your tests using a simple FileAppender instead of a 
RollingFileAppender with size based triggering. Checking for file size 
tends to be rather slow and may greatly bias the results. I suggest the 
following config files:

// ========= log4j.xml
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" 
debug="false">
   <appender name="TestLogfile" class="org.apache.log4j.FileAppender">
     <param name="File" value="testlog4j.log"/>
     <param name="immediateFlush" value="false"/>
     <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.xml
<configuration>
   <appender name="TestLogfile" class="ch.qos.logback.core.FileAppender">
     <file>testlogback.log</file>
     <encoder>
       <Pattern>%d{ISO8601} %5p [%t] %c{0} %X{transactionId} - 
%m%n</Pattern>
     </encoder>
   </appender>

   <root level="debug">
     <appender-ref ref="TestLogfile" />
   </root>
</configuration>

What are the performance results when you run the above scenario?

--
Ceki