[logback-user] logback performance clarification

Tue Mar 13 19:18:49 CET 2007

Nice work on the optimizations. There are a lot of things that may account for the strange results in the original benchmarks. 

In general, microbenchmarks like this aren't very meaningful in Java. See's Sun's Java Tuning White Paper <http://java.sun.com/performance/reference/whitepapers/tuning.html#section3.1>  for a specific discussion of the problems of microbenchmarks. Ryan Lowe (I make no general endorsement of him or his blog) blogged a good example of how things can go very wrong <http://www.ryanlowe.ca/blog/archives/000447_java_microbenchmarks_are_evil.php> . 

Because of HotSpot and other JVM features, you won't run execute same machine code every time you call a method. Depending on your JVM settings, methods may be inlined, optimized and even regressed to interpreted mode all while your application is running. 

The best thing to do is to put a library in your real application and run real benchmarks or use something like JProfiler to see how much time you're spending in different libraries. Microbenchmarks will never tell you very much about how libraries perform in actual use. You just can't simulate the ways the VM will optimize code in the wild, which will often dwarf any differences you find in tight artificial loops.

If you insist on microbenchmarking, here are a few pointers:

·         Run each separate test run in its own VM. This eliminates influence of earlier tests (e.g., GC) on later tests. For example, for each of the five configurations previously mentioned, run a separate VM.

·         Run several hundred thousand iterations before starting the timer. This helps make sure your code gets native compiled before you start. Most applications run long enough to make the initial compile time irrelevant, but it will skew your benchmarks.

·         Use a benchmarking framework like Japex <https://japex.dev.java.net/> .

Hope this is helpful,

  Andy Gerweck 

-----Original Message-----
From: logback-user-bounces at qos.ch [mailto:logback-user-bounces at qos.ch] On Behalf Of Sebastien Pennec
Sent: Tuesday, March 13, 2007 3:41 AM
To: logback users list
Subject: Re: [logback-user] logback performance clarification

Hello Mandeep,

After some research and performance optimizations, here are the results I've 

obtained. Times are shown in nanoseconds per requests, and are an average time after 

1'000'000 requests.

Log4j direct debug call: 442

Log4j tested (isDebugEnabled) debug call: 19

Logback direct debug call: 435

Logback tested (isDebugEnabled) debug call: 10

Logback parametrized debug call: 15

They are rather different than what I had witnessed previously.

First of all, the procedure is closer to a real life example. The 

PerformanceComparator class is nested into a 4-level deep package, and not in the top 

package. Then, only the root loggers have a level set explicitly. That means that 

both logging frameworks have to include level inheritance when deciding to log or not.

This show how logback performs faster than log4j when relying on level inheritance. 

The tested call (using isDebugEnabled()) in logback is almost 2 times faster than its 

log4j counterpart.

Then, we've made a few optimizations in logback's Logger class. There are now less 

method calls, and smarter if statements when recieving the TurboFilter's reply. This 

has made the parametrized call much faster. This form is now faster than log4j's 

isDebugEnabled() form.

Since TurboFilters are a big feature of logback, I should mention that they are 

called when using the direct call or the parametrized call, but also when calling 

isDebugEnabled(). For example, you might want to set your levels to INFO or WARN in 

production, and add a TurboFilter that sets the level to DEBUG for a certain user. 

Having the username in the MDC, you can easily add a TurboFilter that will always 

accept the log requests when they are issued by this user's actions, although the 

logger would not accept such requests coming from any other user.

The isDebugEnabled will then return false every time, except when the current user is 

logged with the username to allow debug level.

I've attached the class I used to get these results at the end of this email. You 

might want to try it on your environment and see if the performance satisfy your 

needs. You will need to checkout logback from its source repository[1][2]

Cheers,

Sébastien

[1]http://logback.qos.ch/repos.html

[2]http://logback.qos.ch/manual/introduction.html#BuildingLogback

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++) {

       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");

   }

}

-- 

Sébastien Pennec

sebastien at qos.ch

Logback: The reliable, generic, fast and flexible logging framework for Java.

http://logback.qos.ch/

_______________________________________________

Logback-user mailing list

Logback-user at qos.ch

http://qos.ch/mailman/listinfo/logback-user

*************************************************************************
The information contained in this communication is confidential, is
intended only for the use of the recipient named above, and may be
legally privileged.

If the reader of this message is not the intended recipient, you are 
hereby notified that any dissemination, distribution or copying of this
communication is strictly prohibited.

If you have received this communication in error, please resend this
communication to the sender and delete the original message or any copy
of it from your computer system.

Thank you.
*************************************************************************
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://qos.ch/pipermail/logback-user/attachments/20070313/719f2454/attachment.htm 