
Hello, Thanks for your email and your observations. I've run your tests, and I think that we should modify a few things to obtain better results. See the class that I've appended at the end of this email. Since we want to calculate the cost of *not* logging, there is no need for configuration files. Only setting the level of the two loggers to info and using debug() methods is enough. We will then see the time it takes to both frameworks to realize that the current logging request needs to be dropped. Also, there will be a difference between the first and following results, because of the just in time compiler. So we should run the tests once without measuring first and then only ouput the results. One more thing is the number of times that we call the debug() method. I think that a number around 100'000 is more appropriate than 500, which is really too low. By running the modified test, I get these values [nanoseconds per calls]: Log4j direct debug call: 370 Log4j tested (isDebugEnabled) debug call: 10 Logback direct debug call: 354 Logback tested (isDebugEnabled) debug call: 3 Logback parametrized debug call: 50 Now about your performance questions: 1. In several documents[1][2] we explain that parametrized logging is way faster than calling the debug method with one argument that is constructed with Strings. That is: logger.debug("Hi, my name is {}.", name); is faster than: logger.debug("Hi, my name is " + name + "."); But it is not true that the parametrized logging is faster than calling isDebugEnabled() before doing anything. I really would like to know where did you read that the parametrized call was faster than the tested call (i.e. calling the printing method inside an if statement testing the level). If we wrote that somewhere, I am going to correct it. However, we can see that logback performs 3 times better than log4j when calling the isDebugEnabled() method. This comes from the fact that logback loggers know their effective level (that is, their level once level inheritance has been taken into consideration). There is no need to walk up the logger hierarchy to know the effective level of a logger. So if performance is critical to you, you have here a good reason to switch :) That said, I was expecting the parametrized call to be faster than what came out of this test, so I'm going to dig some more on this point. 2. I've tried to run the tests several times, but did not experience an invocation running for a much longer time than all the others... and I must admit that it looks strange to me... You might want to run the class that I've attached to this email, so we can see if it performs well in your environment. Regards, Sébastien [1] http://slf4j.org/faq.html#logging_performance [2] http://logback.qos.ch/manual/architecture.html#ParametrizedLogging -- Sébastien Pennec sebastien@qos.ch Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch/ ###################################################### 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 = 100000; 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() { long start = System.nanoTime(); for (int i = 0; i < loop; i++) { log4jlogger.debug("SEE IF THIS IS LOGGED " + i + "."); } return (System.nanoTime() - start)/loop; } private static long log4jTestedDebugCall() { long start = System.nanoTime(); for (int i = 0; i < loop; i++) { if (log4jlogger.isDebugEnabled()) log4jlogger.debug("SEE IF THIS IS LOGGED " + i + "."); } return (System.nanoTime() - start)/loop; } private static long logbackDirectDebugCall() { long start = System.nanoTime(); for (int i = 0; i < loop; i++) { logbacklogger.debug("SEE IF THIS IS LOGGED " + i + "."); } return (System.nanoTime() - start)/loop; } private static long logbackTestedDebugCall() { long start = System.nanoTime(); for (int i = 0; i < loop; i++) { if (logbacklogger.isDebugEnabled()) logbacklogger.debug("SEE IF THIS IS LOGGED " + i + "."); } return (System.nanoTime() - start)/loop; } private static long logbackParametrizedDebugCall() { long start = System.nanoTime(); for (int i = 0; i < loop; i++) { logbacklogger.debug("SEE IF THIS IS LOGGED {}.", i); } return (System.nanoTime() - start)/loop; } private static void initConfig() { //We set the levels of all two loggers to INFO, //so that we do not log anything. log4jlogger.setLevel(org.apache.log4j.Level.INFO); ch.qos.logback.classic.Logger log = (ch.qos.logback.classic.Logger)logbacklogger; log.setLevel(ch.qos.logback.classic.Level.INFO); }