[logback-user] logback performance clarification

[Sebastien Pennec]

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 at 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);
   }