logback performance query (I have some issue with my mail client ..so u might get this mail in symbols..in that case please simply delete that)

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++ ) {<!--
D(["mb","<br>      \nSystem.out.println("############################<WBR>###########");<br>      System.out.println("TEST NUMBER "+j);<br>      System.out.println("############################<WBR>###########");<br>      long start \u003d \nSystem.nanoTime();<br>       for (int i \u003d 0; i < 500; i++ ) {<br>       log4jlogger.debug("SEE IF THIS IS LOGGED " + i + ".");<br>       }<br>          <br>       System.out.println("time taken in nanoseconds in first log4j test is " + (\nSystem.nanoTime() - start));<br>          <br>       start \u003d System.nanoTime();<br>      for (int i \u003d 0; i < 500; i++ ) {<br>        if (log4jlogger.isDebugEnabled())<br>          log4jlogger.debug("SEE IF THIS IS LOGGED " + i + ".");\n<br>      }<br>      System.out.println("time taken in nanoseconds in second log4j test is " + (System.nanoTime() - start));<br><br>     
 Thread.sleep(1000);<br>       start \u003d System.nanoTime();<br>      for (int i \u003d 0; i < 500; i++ ) {\n<br>        logbacklogger.debug("SEE IF THIS IS LOGGED " + i + ".");<br>      }<br>      System.out.println("time taken in nanoseconds in first logback test is " + (System.nanoTime() - start));\n<br><br>       start \u003d System.nanoTime();<br>      for (int i \u003d 0; i < 500; i++ ) {<br>        if (logbacklogger.isDebugEnabled())<br>          logbacklogger.debug("SEE IF THIS IS LOGGED " + i + ".");\n<br>      }<br>      System.out.println("time taken in nanoseconds in second logback test is " + (System.nanoTime() - start));<br><br>      Thread.sleep(1000);<br>      start \u003d System.nanoTime();<br>      for (int i \u003d 0; i < 500; i++ ) {\n<br>        logbacklogger.debug("SEE IF THIS IS LOGGED {}.", i);<br>      }<br>      System.out.println("time taken in nanoseconds in
 third logback test is " + (System.nanoTime() - start));<br>    }<br>\n  }<br>}<br><br><br><br><br>##############################<WBR>#####################LOG4J CONFIG########################",1]
);

//-->

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########################<!--
D(["mb","<WBR>##############<br><?xml version\u003d"1.0" encoding\u003d"UTF-8"?> <br><!DOCTYPE log4j:configuration SYSTEM "../resource/log4j.dtd">\n<br><br><br><log4j:configuration xmlns:log4j\u003d"<a href\u003d\"http://jakarta.apache.org/log4j/\" target\u003d\"_blank\" onclick\u003d\"return top.js.OpenExtLink(window,event,this)\">http://jakarta.apache.org<WBR>/log4j/</a>"<br>                     debug\u003d"false"><br>       <br><br>        <appender name\u003d"TestLogfile" class\u003d"\norg.apache.log4j.RollingFileApp<WBR>ender"><br>                <param name\u003d"File" value\u003d"d:/mandy/Test_Programs<WBR>/testlog4j.log"/><br>                <param name\u003d"MaxFileSize" value\u003d"1000KB"/>\n<br>                <param name\u003d"maxBackupIndex" value\u003d"1"/><br>                <param
 name\u003d"Append" value\u003d"true"/><br>                <layout class\u003d"org.apache.log4j.PatternLayout\n"><br>                         <param name\u003d"ConversionPattern" <br>                              <WBR>                             value\u003d"%d{ISO8601} %5p [%t] %c{1} %X{transactionId} - %m%n"/>\n<br>                </layout><br><br>        </appender><br><br>        <logger name\u003d"mandy.test.programs" additivity\u003d"false"><br>                <level value\u003d"debug"/>\n<br>                <appender-ref ref\u003d"TestLogfile"/><br>        </logger><br><br><br></log4j:configuration><br><br>##############################<WBR>###############LOGBACK CONFIG########################<WBR>####################\n<br><configuration><br><br>    <appender name\u003d"TestLogfile"
 class\u003d"ch.qos.logback.core.FileAppende<WBR>r"><br>        <File>d:/mandy/Test_Programs<WBR>/testlogback.log</File><br>        <Append>false</Append>\n<br>        <Encoding>UTF-8</Encoding><br>        <BufferedIO>true</BufferedIO>",1]
);

//-->##############
<?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><!--
D(["mb","<br>        <ImmediateFlush>true</Immediate<WBR>Flush><br>        <br>        <layout class\u003d"ch.qos.logback.classic.PatternL<WBR>ayout\n"><br>            <Pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</Pattern><br>        </layout><br>    </appender><br>    <br>    <root><br>        <level value\u003d"debug" />\n<br>        <appender-ref ref\u003d"TestLogfile" /><br>    </root><br></configuration><br><br><br>##############################<WBR>###########OUTPUT WITH LOG LEVEL SET TO INFO IN BOTH CONFIG FILES ############################\n<br>##############################<WBR>#########<br>TEST NUMBER 0<br>##############################<WBR>#########<br>time taken in nanoseconds in first log4j test is 1287035<br>time taken in nanoseconds in second log4j test is 425473\n<br>time taken in nanoseconds in first logback test is 1988521<br>time taken in
 nanoseconds in second logback test is 60622<br>time taken in nanoseconds in third logback test is 1378387<br>##############################<WBR>#########\n<br>TEST NUMBER 1<br>##############################<WBR>#########<br>time taken in nanoseconds in first log4j test is 2332139<br>time taken in nanoseconds in second log4j test is 115378<br>time taken in nanoseconds in first logback test is 1550756\n<br>time taken in nanoseconds in second logback test is 50565<br>time taken in nanoseconds in third logback test is 374069<br>##############################<WBR>#########<br>TEST NUMBER 2<br>##############################<WBR>#########\n<br>time taken in nanoseconds in first log4j test is 2050540<br>time taken in nanoseconds in second log4j test is 670755<br>time taken in nanoseconds in first logback test is 846756<br>time taken in nanoseconds in second logback test is 415974\n<br>time taken in nanoseconds in third logback test is
 1142044<br>##############################<WBR>#########<br>TEST NUMBER 3<br>##############################<WBR>#########<br>time taken in nanoseconds in first log4j test is 321828\n",1]
);

//-->
        <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
<!--
D(["mb","<br>time taken in nanoseconds in second log4j test is 43581<br>time taken in nanoseconds in first logback test is 358985<br>time taken in nanoseconds in second logback test is 51962<br>time taken in nanoseconds in third logback test is 127390\n<br>##############################<WBR>#########<br>TEST NUMBER 4<br>##############################<WBR>#########<br>time taken in nanoseconds in first log4j test is 323784<br>time taken in nanoseconds in second log4j test is 43581\n<br>time taken in nanoseconds in first logback test is 362337<br>time taken in nanoseconds in second logback test is 45816<br>time taken in nanoseconds in third logback test is 124597<br>##############################<WBR>#########\n<br>TEST NUMBER 5<br>##############################<WBR>#########<br>time taken in nanoseconds in first log4j test is 326578<br>time taken in nanoseconds in second log4j test is 43581<br>time taken in nanoseconds in first logback test is 5767493\n<br>time taken in
 nanoseconds in second logback test is 25981<br>time taken in nanoseconds in third logback test is 103365<br>##############################<WBR>#########<br>TEST NUMBER 6<br>##############################<WBR>#########\n<br>time taken in nanoseconds in first log4j test is 261206<br>time taken in nanoseconds in second log4j test is 28775<br>time taken in nanoseconds in first logback test is 239416<br>time taken in nanoseconds in second logback test is 5867\n<br>time taken in nanoseconds in third logback test is 59505<br>##############################<WBR>#########<br>TEST NUMBER 7<br>##############################<WBR>#########<br>time taken in nanoseconds in first log4j test is 223492\n<br>time taken in nanoseconds in second log4j test is 12851<br>time taken in nanoseconds in first logback test is 235784<br>time taken in nanoseconds in second logback test is 5867<br>time taken in nanoseconds in third logback test is
 58667\n<br>##############################<WBR>#########<br>TEST NUMBER 8<br>##############################<WBR>#########<br>time taken in nanoseconds in first log4j test is 220977",1]
);

//-->
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<!--
D(["mb","<br>time taken in nanoseconds in second log4j test is 12851\n<br>time taken in nanoseconds in first logback test is 238299<br>time taken in nanoseconds in second logback test is 5867<br>time taken in nanoseconds in third logback test is 61460<br>##############################<WBR>#########\n<br>TEST NUMBER 9<br>##############################<WBR>#########<br>time taken in nanoseconds in first log4j test is 223212<br>time taken in nanoseconds in second log4j test is 12851<br>time taken in nanoseconds in first logback test is 237461\n<br>time taken in nanoseconds in second logback test is 5308<br>time taken in nanoseconds in third logback test is 62019<br><br><br><br>##############################<WBR>###########OUTPUT WITH LOG LEVEL SET TO DEBUG IN BOTH CONFIG FILES ############################\n<br>##############################<WBR>#########<br>TEST NUMBER 0<br>##############################<WBR>#########<br>time taken in nanoseconds in first log4j test is
 85486004<br>time taken in nanoseconds in second log4j test is 35743649\n<br>time taken in nanoseconds in first logback test is 22309540<br>time taken in nanoseconds in second logback test is 7795963<br>time taken in nanoseconds in third logback test is 19922365<br>##############################<WBR>#########\n<br>TEST NUMBER 1<br>##############################<WBR>#########<br>time taken in nanoseconds in first log4j test is 39167827<br>time taken in nanoseconds in second log4j test is 33095826<br>time taken in nanoseconds in first logback test is 3618616\n<br>time taken in nanoseconds in second logback test is 2657601<br>time taken in nanoseconds in third logback test is 6253309<br>##############################<WBR>#########<br>TEST NUMBER 2<br>##############################<WBR>#########\n<br>time taken in nanoseconds in first log4j test is 12328941<br>time taken in nanoseconds in second log4j test is 13580218<br>time taken in nanoseconds in first logback test is
 2401422<br>time taken in nanoseconds in second logback test is 2868521\n<br>time taken in nanoseconds in third logback test is 4724902",1]
);

//-->
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<!--
D(["mb","<br>##############################<WBR>#########<br>TEST NUMBER 3<br>##############################<WBR>#########<br>time taken in nanoseconds in first log4j test is 12460243\n<br>time taken in nanoseconds in second log4j test is 11747583<br>time taken in nanoseconds in first logback test is 2559543<br>time taken in nanoseconds in second logback test is 2694477<br>time taken in nanoseconds in third logback test is 4801727\n<br>##############################<WBR>#########<br>TEST NUMBER 4<br>##############################<WBR>#########<br>time taken in nanoseconds in first log4j test is 11915481<br>time taken in nanoseconds in second log4j test is 12330618\n<br>time taken in nanoseconds in first logback test is 2379073<br>time taken in nanoseconds in second logback test is 2888076<br>time taken in nanoseconds in third logback test is 2698667<br>##############################<WBR>#########\n<br>TEST NUMBER 5<br>##############################<WBR>#########<br>time
 taken in nanoseconds in first log4j test is 15098288<br>time taken in nanoseconds in second log4j test is 11025144<br>time taken in nanoseconds in first logback test is 8196013\n<br>time taken in nanoseconds in second logback test is 2065067<br>time taken in nanoseconds in third logback test is 2888076<br>##############################<WBR>#########<br>TEST NUMBER 6<br>##############################<WBR>#########\n<br>time taken in nanoseconds in first log4j test is 10594922<br>time taken in nanoseconds in second log4j test is 9976687<br>time taken in nanoseconds in first logback test is 2229892<br>time taken in nanoseconds in second logback test is 2172902\n<br>time taken in nanoseconds in third logback test is 2692800<br>##############################<WBR>#########<br>TEST NUMBER 7<br>##############################<WBR>#########<br>time taken in nanoseconds in first log4j test is 10521728\n<br>time taken in nanoseconds in second log4j test is 10123354<br>time taken in
 nanoseconds in first logback test is 2148597<br>time taken in nanoseconds in second logback test is 2135746",1]
);

//-->
#######################################
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<!--
D(["mb","<br>time taken in nanoseconds in third logback test is 2933893\n<br>##############################<WBR>#########<br>TEST NUMBER 8<br>##############################<WBR>#########<br>time taken in nanoseconds in first log4j test is 10182579<br>time taken in nanoseconds in second log4j test is 10013563\n<br>time taken in nanoseconds in first logback test is 2300851<br>time taken in nanoseconds in second logback test is 2087137<br>time taken in nanoseconds in third logback test is 2761803<br>##############################<WBR>#########\n<br>TEST NUMBER 9<br>##############################<WBR>#########<br>time taken in nanoseconds in first log4j test is 9720230<br>time taken in nanoseconds in second log4j test is 10646605<br>time taken in nanoseconds in first logback test is 2647264\n<br>time taken in nanoseconds in second logback test is 2164800<br>time taken in nanoseconds in third logback test is 2681905<br><br>\n",0]
);
D(["ce"]);

//-->
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

____________________________________________________________________________________
Food fight? Enjoy some healthy debate 
in the Yahoo! Answers Food & Drink Q&A.
http://answers.yahoo.com/dir/?link=list&sid=396545367

Mandeep Singh

tags

participants (1)