[logback-user] logback performace going down

21 May 2007

      Hi,

I had downloaded the logback version 0.9.2 sometime back and had done some performance comparison vis a vis log4j. At that time the tested call (logger.isDebugEnabled) was atleast 3 times faster in logback then log4j. But just today i downloaded the 0.9.5 version and it seems that due to some changes the performance has been hit . Now logback is a bit slower then log4j for the same call . (Although i must add that the performance of parameterized call has improved, and it now takes half of the time as compared to 0.9.2)

I am pasting the code used for the test.

- Mandeep

====================================================================================================
====================================================================================================

package mandy.test.programs;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class LogTester2 {

  static Logger logbacklogger = LoggerFactory.getLogger(LogTester2.class);
  static org.apache.log4j.Logger log4jlogger = org.apache.log4j.Logger.getLogger(LogTester2.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++ ) {
      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");
  }

}

____________________________________________________________________________________Need a vacation? Get great deals
to amazing places on Yahoo! Travel.
http://travel.yahoo.com/

[logback-user] logback performace going down

Mandeep Singh