[logback-user] logback performance clarification

9 Mar 2007

      Hi,

I I am a new user of logback and would like to use it in my project.
Currently we are using log4j, but we have very strict performance
requirements and it would be gr8 if logback performs better then log4j. I
did some preliminary tests to compare the performace of the two ..and i
observed that at some places logback is certainly better , but i also
observed a behaviour which is contrary to what is described in the
documentation. I am attaching the source code and my config files for the
test . The queries I have are as following -

1. The documentation says that the "logbacklogger.debug("SEE IF THIS IS
LOGGED {}.", i);"  is faster then

if (logbacklogger.isDebugEnabled())
          logbacklogger.debug("SEE IF THIS IS LOGGED " + i + ".");

but i observed that this is only true if the logging is configured for debug
. For any other logging level the second approach is still more performant.
This means that in a production env I must still have the check for
isDebugEnabled. Is that intended or am i missing something.

2. Something very strange that i observed in my test was that if i run my
outer loop 10 times then always at the 7th invocation the logback took much
longer time. I was able to get this behaviour consistently.

Anyways for the time being I am attaching my source code and the config
files below ...maybe somebody can point out the errors or way of
improvement.

########################################JAVA
FILE##################################################
package mandy.test.programs;

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

public class Logtester {

  static Logger logbacklogger = LoggerFactory.getLogger(Logtester.class);
  static org.apache.log4j.Logger log4jlogger =
org.apache.log4j.Logger.getLogger(Logtester.class);

  public static void main(String[] args) throws InterruptedException {

    for (int j = 0; j < 5; j++ ) {
      System.out.println("#######################################");
      System.out.println("TEST NUMBER "+j);
      System.out.println("#######################################");
      long start = System.nanoTime();
       for (int i = 0; i < 500; i++ ) {
       log4jlogger.debug("SEE IF THIS IS LOGGED " + i + ".");
       }

       System.out.println("time taken in nanoseconds in first log4j test is
" + (System.nanoTime() - start));

       start = System.nanoTime();
      for (int i = 0; i < 500; i++ ) {
        if (log4jlogger.isDebugEnabled())
          log4jlogger.debug("SEE IF THIS IS LOGGED " + i + ".");
      }
      System.out.println("time taken in nanoseconds in second log4j test is
" + (System.nanoTime() - start));

      Thread.sleep(1000);
       start = System.nanoTime();
      for (int i = 0; i < 500; i++ ) {
        logbacklogger.debug("SEE IF THIS IS LOGGED " + i + ".");
      }
      System.out.println("time taken in nanoseconds in first logback test is
" + (System.nanoTime() - start));

       start = System.nanoTime();
      for (int i = 0; i < 500; i++ ) {
        if (logbacklogger.isDebugEnabled())
          logbacklogger.debug("SEE IF THIS IS LOGGED " + i + ".");
      }
      System.out.println("time taken in nanoseconds in second logback test
is " + (System.nanoTime() - start));

      Thread.sleep(1000);
      start = System.nanoTime();
      for (int i = 0; i < 500; i++ ) {
        logbacklogger.debug("SEE IF THIS IS LOGGED {}.", i);
      }
      System.out.println("time taken in nanoseconds in third logback test is
" + (System.nanoTime() - start));
    }
  }
}

###################################################LOG4J
CONFIG######################################
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "../resource/log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/"
                     debug="false">

        <appender name="TestLogfile" class="
org.apache.log4j.RollingFileAppender">
                <param name="File"
value="d:/mandy/Test_Programs/testlog4j.log"/>
                <param name="MaxFileSize" value="1000KB"/>
                <param name="maxBackupIndex" value="1"/>
                <param name="Append" value="true"/>
                <layout class="org.apache.log4j.PatternLayout">
                         <param name="ConversionPattern"

value="%d{ISO8601} %5p [%t] %c{1} %X{transactionId} - %m%n"/>
                </layout>

        </appender>

        <logger name="mandy.test.programs" additivity="false">
                <level value="debug"/>
                <appender-ref ref="TestLogfile"/>
        </logger>

</log4j:configuration>

#############################################LOGBACK
CONFIG############################################
<configuration>

    <appender name="TestLogfile" class="ch.qos.logback.core.FileAppender">
        <File>d:/mandy/Test_Programs/testlogback.log</File>
        <Append>false</Append>
        <Encoding>UTF-8</Encoding>
        <BufferedIO>true</BufferedIO>
        <ImmediateFlush>true</ImmediateFlush>

        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>%-4relative [%thread] %-5level %logger{35} -
%msg%n</Pattern>
        </layout>
    </appender>

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

#########################################OUTPUT WITH LOG LEVEL SET TO INFO
IN BOTH CONFIG FILES ############################
#######################################
TEST NUMBER 0
#######################################
time taken in nanoseconds in first log4j test is 1287035
time taken in nanoseconds in second log4j test is 425473
time taken in nanoseconds in first logback test is 1988521
time taken in nanoseconds in second logback test is 60622
time taken in nanoseconds in third logback test is 1378387
#######################################
TEST NUMBER 1
#######################################
time taken in nanoseconds in first log4j test is 2332139
time taken in nanoseconds in second log4j test is 115378
time taken in nanoseconds in first logback test is 1550756
time taken in nanoseconds in second logback test is 50565
time taken in nanoseconds in third logback test is 374069
#######################################
TEST NUMBER 2
#######################################
time taken in nanoseconds in first log4j test is 2050540
time taken in nanoseconds in second log4j test is 670755
time taken in nanoseconds in first logback test is 846756
time taken in nanoseconds in second logback test is 415974
time taken in nanoseconds in third logback test is 1142044
#######################################
TEST NUMBER 3
#######################################
time taken in nanoseconds in first log4j test is 321828
time taken in nanoseconds in second log4j test is 43581
time taken in nanoseconds in first logback test is 358985
time taken in nanoseconds in second logback test is 51962
time taken in nanoseconds in third logback test is 127390
#######################################
TEST NUMBER 4
#######################################
time taken in nanoseconds in first log4j test is 323784
time taken in nanoseconds in second log4j test is 43581
time taken in nanoseconds in first logback test is 362337
time taken in nanoseconds in second logback test is 45816
time taken in nanoseconds in third logback test is 124597
#######################################
TEST NUMBER 5
#######################################
time taken in nanoseconds in first log4j test is 326578
time taken in nanoseconds in second log4j test is 43581
time taken in nanoseconds in first logback test is 5767493
time taken in nanoseconds in second logback test is 25981
time taken in nanoseconds in third logback test is 103365
#######################################
TEST NUMBER 6
#######################################
time taken in nanoseconds in first log4j test is 261206
time taken in nanoseconds in second log4j test is 28775
time taken in nanoseconds in first logback test is 239416
time taken in nanoseconds in second logback test is 5867
time taken in nanoseconds in third logback test is 59505
#######################################
TEST NUMBER 7
#######################################
time taken in nanoseconds in first log4j test is 223492
time taken in nanoseconds in second log4j test is 12851
time taken in nanoseconds in first logback test is 235784
time taken in nanoseconds in second logback test is 5867
time taken in nanoseconds in third logback test is 58667
#######################################
TEST NUMBER 8
#######################################
time taken in nanoseconds in first log4j test is 220977
time taken in nanoseconds in second log4j test is 12851
time taken in nanoseconds in first logback test is 238299
time taken in nanoseconds in second logback test is 5867
time taken in nanoseconds in third logback test is 61460
#######################################
TEST NUMBER 9
#######################################
time taken in nanoseconds in first log4j test is 223212
time taken in nanoseconds in second log4j test is 12851
time taken in nanoseconds in first logback test is 237461
time taken in nanoseconds in second logback test is 5308
time taken in nanoseconds in third logback test is 62019

#########################################OUTPUT WITH LOG LEVEL SET TO DEBUG
IN BOTH CONFIG FILES ############################
#######################################
TEST NUMBER 0
#######################################
time taken in nanoseconds in first log4j test is 85486004
time taken in nanoseconds in second log4j test is 35743649
time taken in nanoseconds in first logback test is 22309540
time taken in nanoseconds in second logback test is 7795963
time taken in nanoseconds in third logback test is 19922365
#######################################
TEST NUMBER 1
#######################################
time taken in nanoseconds in first log4j test is 39167827
time taken in nanoseconds in second log4j test is 33095826
time taken in nanoseconds in first logback test is 3618616
time taken in nanoseconds in second logback test is 2657601
time taken in nanoseconds in third logback test is 6253309
#######################################
TEST NUMBER 2
#######################################
time taken in nanoseconds in first log4j test is 12328941
time taken in nanoseconds in second log4j test is 13580218
time taken in nanoseconds in first logback test is 2401422
time taken in nanoseconds in second logback test is 2868521
time taken in nanoseconds in third logback test is 4724902
#######################################
TEST NUMBER 3
#######################################
time taken in nanoseconds in first log4j test is 12460243
time taken in nanoseconds in second log4j test is 11747583
time taken in nanoseconds in first logback test is 2559543
time taken in nanoseconds in second logback test is 2694477
time taken in nanoseconds in third logback test is 4801727
#######################################
TEST NUMBER 4
#######################################
time taken in nanoseconds in first log4j test is 11915481
time taken in nanoseconds in second log4j test is 12330618
time taken in nanoseconds in first logback test is 2379073
time taken in nanoseconds in second logback test is 2888076
time taken in nanoseconds in third logback test is 2698667
#######################################
TEST NUMBER 5
#######################################
time taken in nanoseconds in first log4j test is 15098288
time taken in nanoseconds in second log4j test is 11025144
time taken in nanoseconds in first logback test is 8196013
time taken in nanoseconds in second logback test is 2065067
time taken in nanoseconds in third logback test is 2888076
#######################################
TEST NUMBER 6
#######################################
time taken in nanoseconds in first log4j test is 10594922
time taken in nanoseconds in second log4j test is 9976687
time taken in nanoseconds in first logback test is 2229892
time taken in nanoseconds in second logback test is 2172902
time taken in nanoseconds in third logback test is 2692800
#######################################
TEST NUMBER 7
#######################################
time taken in nanoseconds in first log4j test is 10521728
time taken in nanoseconds in second log4j test is 10123354
time taken in nanoseconds in first logback test is 2148597
time taken in nanoseconds in second logback test is 2135746
time taken in nanoseconds in third logback test is 2933893
#######################################
TEST NUMBER 8
#######################################
time taken in nanoseconds in first log4j test is 10182579
time taken in nanoseconds in second log4j test is 10013563
time taken in nanoseconds in first logback test is 2300851
time taken in nanoseconds in second logback test is 2087137
time taken in nanoseconds in third logback test is 2761803
#######################################
TEST NUMBER 9
#######################################
time taken in nanoseconds in first log4j test is 9720230
time taken in nanoseconds in second log4j test is 10646605
time taken in nanoseconds in first logback test is 2647264
time taken in nanoseconds in second logback test is 2164800
time taken in nanoseconds in third logback test is 2681905

[logback-user] logback performance clarification

mandeep singh