March 2007 - logback-user - mailman3.qos.ch

Re: [logback-user] logback performance clarification
by Mandeep Singh 13 Mar '07

13 Mar '07

Hello Sebastian, Thanks a lot for ur replies and all the efforts that u have put in into this great product. I will surely test this new code. In ur previous reply u had asked me the source of my assumption that the parameterized call is faster then "isDebugEnabled". Well I misinterpreted the "10 reasons to use logback" slideshow that is available on the logback site .. I am pasting the contents of the slide (Slide number 21) that confused me, maybe u can consider rewording it - Integer entry = new Interger(50); logger.debug("The entry is "+entry+"."); can be optimized as: if(logger.isDebugEnabled()) { logger.debug("The entry is "+entry+"."); } or better yet: logger.debug("The entry is {}.", entry); so u see that the second and third point are not actually related ...:) Also I have another small query , my project uses a mixture of commons logging and log4j, also some of the thirdparty libraries that we use, are using commons. Where does logback fit in commons ? Can u point me a doc which i can refer for the same. once again thanks for all ur help. regards Mandeep ----- Original Message ---- From: Sebastien Pennec <sebastien(a)qos.ch> To: logback users list <logback-user(a)qos.ch> Sent: Tuesday, March 13, 2007 11:41:16 AM 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(a)qos.ch Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch/ _______________________________________________ Logback-user mailing list Logback-user(a)qos.ch http://qos.ch/mailman/listinfo/logback-user ____________________________________________________________________________________ Bored stiff? Loosen up... Download and play hundreds of games for free on Yahoo! Games. http://games.yahoo.com/games/front

2 1

LoggerContext not using java.util.concurrent?
by Anders Wallgren 13 Mar '07

13 Mar '07

Is there a reason logback isn't taking advantage of the java.util.concurrent package? For example, LoggerContext uses a Hashtable (which synchronizes all access) rather than a ConcurrentHashMap, which supports lock-free read access. anders -- View this message in context: http://www.nabble.com/LoggerContext-not-using-java.util.concurrent--tf33942… Sent from the Logback User mailing list archive at Nabble.com.

2 1

Should logback.xml be in part of a web app?
by Keith 12 Mar '07

12 Mar '07

Hi: Can you please give some recommendation if I should include logback.xml in an EAR or outside on a file system? In the past, I would put it outside on a file system so that I can change the logging level on the fly when a need arises to log in detail. However, in this new company which I recently join, it prefers that everything be packaged in a EAR to "reduce work" for the deployment team. Given such option, how do I change the level of logging easily if the logback.xml is packaged in an EAR? Can I still be able to change the level of logging programmatically on the fly, or perhaps using JMX? Will I be able to save the change into the file in the EAR? Thanks, Keith

2 1

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)
by Mandeep Singh 09 Mar '07

09 Mar '07

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 ____________________________________________________________________________________ Food fight? Enjoy some healthy debate in the Yahoo! Answers Food & Drink Q&A. http://answers.yahoo.com/dir/?link=list&sid=396545367

1 0

[ANN] Release of logback 0.9.2
by Sebastien Pennec 05 Mar '07

05 Mar '07

March 5th, 2007 - Release of version 0.9.2 The logback team is proud to announce the immediate availability of logback version 0.9.2. Here is a summary of the changes: The logback manual and complete website is now located in the docs/ directory of the distribution. Enjoy, Sébastien -- Sébastien Pennec sebastien(a)qos.ch Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch/

1 0

[ANN] Release of logback 0.9.1
by Sebastien Pennec 05 Mar '07

05 Mar '07

March 5th, 2007 - Release of version 0.9.1 The logback team is proud to announce the immediate availability of logback version 0.9.1. Here is a summary of the changes: - Logback-classic now depends on SLF4J version 1.3.0 instead of 1.2. - Numerous improvements to the documentation. - Bug #46 (see [1]) reported by Mark Renyolds has been fixed. The TimeUtilTest should now run fine under any time zone. - Bug #45 (see [2]), also reported by Mark Reynolds has, been fixed. There should be no ClassCastException thrown anymore when passing an Object to the printing methods using the log4j-bridge module. You can download logback, including full source code, class files and documentation on our download page, shown below. http://logback.qos.ch/download.html You can receive logback related announcements by subscribing to the logback announce mailing list. To subscribe to logback-announce list, please visit the following URL. http://qos.ch/mailman/listinfo/logback-announce Given that logback's repository is automatically synchronized with the Maven repository on Ibiblio, the artifacts associated with logback 0.9.1 should be available on Ibilio within the next four hours or so. Enjoy, [1] http://bugzilla.qos.ch/show_bug.cgi?id=46 [2] http://bugzilla.qos.ch/show_bug.cgi?id=45 -- Sébastien Pennec sebastien(a)qos.ch Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch/

1 0

Logback + slf4j 1.3.0
by Franck Routier 02 Mar '07

02 Mar '07

Hi, will logback-0.9 run with slf4j-1.3.0 or should I wait for a release ? Regards, Franck

2 1

[newbie] Setting up a project
by Alexandre Jaquet 02 Mar '07

02 Mar '07

Hi, I'm new to logback and I'm trying to setting up a test project, who will use it. When I used log4j I simply added a file log4.properties on my src root and define some paramaters. My question is how to do the same, and wich paramaters I've to set. Thanks for your support. Regards. Alexandre Jaquet

2 8