<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40">
<head>
<meta http-equiv=Content-Type content="text/html; charset=iso-8859-1">
<meta name=Generator content="Microsoft Word 12 (filtered medium)">
<style>
<!--
/* Font Definitions */
@font-face
{font-family:Wingdings;
panose-1:5 0 0 0 0 0 0 0 0 0;}
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
{font-family:Verdana;
panose-1:2 11 6 4 3 5 4 4 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0in;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri","sans-serif";}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:blue;
text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
{mso-style-priority:99;
color:purple;
text-decoration:underline;}
p.MsoPlainText, li.MsoPlainText, div.MsoPlainText
{mso-style-priority:99;
mso-style-link:"Plain Text Char";
margin:0in;
margin-bottom:.0001pt;
font-size:10.0pt;
font-family:"Courier New";}
span.PlainTextChar
{mso-style-name:"Plain Text Char";
mso-style-priority:99;
mso-style-link:"Plain Text";
font-family:"Courier New";}
.MsoChpDefault
{mso-style-type:export-only;}
@page Section1
{size:8.5in 11.0in;
margin:1.0in 1.0in 1.0in 1.0in;}
div.Section1
{page:Section1;}
/* List Definitions */
@list l0
{mso-list-id:1533807216;
mso-list-type:hybrid;
mso-list-template-ids:1351227764 67698689 67698691 67698693 67698689 67698691 67698693 67698689 67698691 67698693;}
@list l0:level1
{mso-level-number-format:bullet;
mso-level-text:\F0B7;
mso-level-tab-stop:none;
mso-level-number-position:left;
text-indent:-.25in;
font-family:Symbol;}
ol
{margin-bottom:0in;}
ul
{margin-bottom:0in;}
-->
</style>
<!--[if gte mso 9]><xml>
<o:shapedefaults v:ext="edit" spidmax="1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext="edit">
<o:idmap v:ext="edit" data="1" />
</o:shapelayout></xml><![endif]-->
</head>
<body lang=EN-US link=blue vlink=purple>
<div class=Section1>
<p class=MsoPlainText><span style='font-family:"Verdana","sans-serif"'>Nice
work on the optimizations. There are a lot of things that may account for the
strange results in the original benchmarks. <o:p></o:p></span></p>
<p class=MsoPlainText><span style='font-family:"Verdana","sans-serif"'><o:p> </o:p></span></p>
<p class=MsoPlainText><span style='font-family:"Verdana","sans-serif"'>In
general, microbenchmarks like this aren't very meaningful in Java. See's Sun's <a
href="http://java.sun.com/performance/reference/whitepapers/tuning.html#section3.1">Java
Tuning White Paper</a> for a specific discussion of the problems of
microbenchmarks. Ryan Lowe (I make no general endorsement of him or his blog) blogged
a <a
href="http://www.ryanlowe.ca/blog/archives/000447_java_microbenchmarks_are_evil.php">good
example of how things can go very wrong</a>. <o:p></o:p></span></p>
<p class=MsoPlainText><span style='font-family:"Verdana","sans-serif"'><o:p> </o:p></span></p>
<p class=MsoPlainText><span style='font-family:"Verdana","sans-serif"'>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. <o:p></o:p></span></p>
<p class=MsoPlainText><span style='font-family:"Verdana","sans-serif"'><o:p> </o:p></span></p>
<p class=MsoPlainText><span style='font-family:"Verdana","sans-serif"'>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.<o:p></o:p></span></p>
<p class=MsoPlainText><span style='font-family:"Verdana","sans-serif"'><o:p> </o:p></span></p>
<p class=MsoPlainText><span style='font-family:"Verdana","sans-serif"'>If you
insist on microbenchmarking, here are a few pointers:<o:p></o:p></span></p>
<p class=MsoPlainText style='mso-margin-top-alt:6.0pt;margin-right:0in;
margin-bottom:0in;margin-left:.5in;margin-bottom:.0001pt;text-indent:-.25in;
mso-list:l0 level1 lfo1'><![if !supportLists]><span style='font-family:Symbol'><span
style='mso-list:Ignore'>ˇ<span style='font:7.0pt "Times New Roman"'>
</span></span></span><![endif]><span style='font-family:"Verdana","sans-serif"'>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.<o:p></o:p></span></p>
<p class=MsoPlainText style='mso-margin-top-alt:6.0pt;margin-right:0in;
margin-bottom:0in;margin-left:.5in;margin-bottom:.0001pt;text-indent:-.25in;
mso-list:l0 level1 lfo1'><![if !supportLists]><span style='font-family:Symbol'><span
style='mso-list:Ignore'>ˇ<span style='font:7.0pt "Times New Roman"'>
</span></span></span><![endif]><span style='font-family:"Verdana","sans-serif"'>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.<o:p></o:p></span></p>
<p class=MsoPlainText style='mso-margin-top-alt:6.0pt;margin-right:0in;
margin-bottom:0in;margin-left:.5in;margin-bottom:.0001pt;text-indent:-.25in;
mso-list:l0 level1 lfo1'><![if !supportLists]><span style='font-family:Symbol'><span
style='mso-list:Ignore'>ˇ<span style='font:7.0pt "Times New Roman"'>
</span></span></span><![endif]><span style='font-family:"Verdana","sans-serif"'>Use
a benchmarking framework like <a href="https://japex.dev.java.net/">Japex</a>.<o:p></o:p></span></p>
<p class=MsoPlainText><span style='font-family:"Verdana","sans-serif"'><o:p> </o:p></span></p>
<p class=MsoPlainText><span style='font-family:"Verdana","sans-serif"'>Hope
this is helpful,<o:p></o:p></span></p>
<p class=MsoPlainText><i><span style='font-family:"Verdana","sans-serif"'>
Andy Gerweck <o:p></o:p></span></i></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>-----Original Message-----<br>
From: logback-user-bounces@qos.ch [mailto:logback-user-bounces@qos.ch] On
Behalf Of Sebastien Pennec<br>
Sent: Tuesday, March 13, 2007 3:41 AM<br>
To: logback users list<br>
Subject: Re: [logback-user] logback performance clarification<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>Hello Mandeep,<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>After some research and performance optimizations, here
are the results I've <o:p></o:p></p>
<p class=MsoPlainText>obtained. Times are shown in nanoseconds per requests,
and are an average time after <o:p></o:p></p>
<p class=MsoPlainText>1'000'000 requests.<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>Log4j direct debug call: 442<o:p></o:p></p>
<p class=MsoPlainText>Log4j tested (isDebugEnabled) debug call: 19<o:p></o:p></p>
<p class=MsoPlainText>Logback direct debug call: 435<o:p></o:p></p>
<p class=MsoPlainText>Logback tested (isDebugEnabled) debug call: 10<o:p></o:p></p>
<p class=MsoPlainText>Logback parametrized debug call: 15<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>They are rather different than what I had witnessed
previously.<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>First of all, the procedure is closer to a real life
example. The <o:p></o:p></p>
<p class=MsoPlainText>PerformanceComparator class is nested into a 4-level deep
package, and not in the top <o:p></o:p></p>
<p class=MsoPlainText>package. Then, only the root loggers have a level set
explicitly. That means that <o:p></o:p></p>
<p class=MsoPlainText>both logging frameworks have to include level inheritance
when deciding to log or not.<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>This show how logback performs faster than log4j when
relying on level inheritance. <o:p></o:p></p>
<p class=MsoPlainText>The tested call (using isDebugEnabled()) in logback is
almost 2 times faster than its <o:p></o:p></p>
<p class=MsoPlainText>log4j counterpart.<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>Then, we've made a few optimizations in logback's Logger
class. There are now less <o:p></o:p></p>
<p class=MsoPlainText>method calls, and smarter if statements when recieving
the TurboFilter's reply. This <o:p></o:p></p>
<p class=MsoPlainText>has made the parametrized call much faster. This form is
now faster than log4j's <o:p></o:p></p>
<p class=MsoPlainText>isDebugEnabled() form.<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>Since TurboFilters are a big feature of logback, I should
mention that they are <o:p></o:p></p>
<p class=MsoPlainText>called when using the direct call or the parametrized
call, but also when calling <o:p></o:p></p>
<p class=MsoPlainText>isDebugEnabled(). For example, you might want to set your
levels to INFO or WARN in <o:p></o:p></p>
<p class=MsoPlainText>production, and add a TurboFilter that sets the level to
DEBUG for a certain user. <o:p></o:p></p>
<p class=MsoPlainText>Having the username in the MDC, you can easily add a
TurboFilter that will always <o:p></o:p></p>
<p class=MsoPlainText>accept the log requests when they are issued by this
user's actions, although the <o:p></o:p></p>
<p class=MsoPlainText>logger would not accept such requests coming from any
other user.<o:p></o:p></p>
<p class=MsoPlainText>The isDebugEnabled will then return false every time,
except when the current user is <o:p></o:p></p>
<p class=MsoPlainText>logged with the username to allow debug level.<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>I've attached the class I used to get these results at
the end of this email. You <o:p></o:p></p>
<p class=MsoPlainText>might want to try it on your environment and see if the
performance satisfy your <o:p></o:p></p>
<p class=MsoPlainText>needs. You will need to checkout logback from its source
repository[1][2]<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>Cheers,<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>Sébastien<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>[1]http://logback.qos.ch/repos.html<o:p></o:p></p>
<p class=MsoPlainText>[2]http://logback.qos.ch/manual/introduction.html#BuildingLogback<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>package perfTest.ch.qos.logback;<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>import org.slf4j.Logger;<o:p></o:p></p>
<p class=MsoPlainText>import org.slf4j.LoggerFactory;<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>public class PerformanceComparator {<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText> static Logger logbacklogger = LoggerFactory<o:p></o:p></p>
<p class=MsoPlainText> .getLogger(PerformanceComparator.class);<o:p></o:p></p>
<p class=MsoPlainText> static org.apache.log4j.Logger log4jlogger =
org.apache.log4j.Logger<o:p></o:p></p>
<p class=MsoPlainText> .getLogger(PerformanceComparator.class);<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText> // How many times should we try to log:<o:p></o:p></p>
<p class=MsoPlainText> static int loop = 1000000;<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText> public static void main(String[] args) throws
InterruptedException {<o:p></o:p></p>
<p class=MsoPlainText> initConfig();<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText> // Let's run once for Just In Time compiler<o:p></o:p></p>
<p class=MsoPlainText> log4jDirectDebugCall();<o:p></o:p></p>
<p class=MsoPlainText> log4jTestedDebugCall();<o:p></o:p></p>
<p class=MsoPlainText> logbackDirectDebugCall();<o:p></o:p></p>
<p class=MsoPlainText> logbackTestedDebugCall();<o:p></o:p></p>
<p class=MsoPlainText> logbackParametrizedDebugCall();<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText> // let's run the tests and display the results:<o:p></o:p></p>
<p class=MsoPlainText> long result1 = log4jDirectDebugCall();<o:p></o:p></p>
<p class=MsoPlainText> long result2 = log4jTestedDebugCall();<o:p></o:p></p>
<p class=MsoPlainText> long result3 = logbackDirectDebugCall();<o:p></o:p></p>
<p class=MsoPlainText> long result4 = logbackTestedDebugCall();<o:p></o:p></p>
<p class=MsoPlainText> long result5 = logbackParametrizedDebugCall();<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>
System.out.println("###############################################");<o:p></o:p></p>
<p class=MsoPlainText> System.out.println("Log4j direct debug call:
" + result1);<o:p></o:p></p>
<p class=MsoPlainText> System.out.println("Log4j tested
(isDebugEnabled) debug call: " + result2);<o:p></o:p></p>
<p class=MsoPlainText> System.out.println("Logback direct debug call:
" + result3);<o:p></o:p></p>
<p class=MsoPlainText> System.out<o:p></o:p></p>
<p class=MsoPlainText> .println("Logback tested (isDebugEnabled)
debug call: " + result4);<o:p></o:p></p>
<p class=MsoPlainText> System.out.println("Logback parametrized debug
call: " + result5);<o:p></o:p></p>
<p class=MsoPlainText>
System.out.println("###############################################");<o:p></o:p></p>
<p class=MsoPlainText> }<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText> private static long log4jDirectDebugCall() {<o:p></o:p></p>
<p class=MsoPlainText> Integer j = new Integer(2);<o:p></o:p></p>
<p class=MsoPlainText> long start = System.nanoTime();<o:p></o:p></p>
<p class=MsoPlainText> for (int i = 0; i < loop; i++) {<o:p></o:p></p>
<p class=MsoPlainText> log4jlogger.debug("SEE IF THIS IS LOGGED
" + j + ".");<o:p></o:p></p>
<p class=MsoPlainText> }<o:p></o:p></p>
<p class=MsoPlainText> return (System.nanoTime() - start) / loop;<o:p></o:p></p>
<p class=MsoPlainText> }<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText> private static long log4jTestedDebugCall() {<o:p></o:p></p>
<p class=MsoPlainText> Integer j = new Integer(2);<o:p></o:p></p>
<p class=MsoPlainText> long start = System.nanoTime();<o:p></o:p></p>
<p class=MsoPlainText> for (int i = 0; i < loop; i++) {<o:p></o:p></p>
<p class=MsoPlainText> if (log4jlogger.isDebugEnabled()) {<o:p></o:p></p>
<p class=MsoPlainText> log4jlogger.debug("SEE IF THIS IS LOGGED
" + j + ".");<o:p></o:p></p>
<p class=MsoPlainText> }<o:p></o:p></p>
<p class=MsoPlainText> }<o:p></o:p></p>
<p class=MsoPlainText> return (System.nanoTime() - start) / loop;<o:p></o:p></p>
<p class=MsoPlainText> }<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText> private static long logbackDirectDebugCall() {<o:p></o:p></p>
<p class=MsoPlainText> Integer j = new Integer(2);<o:p></o:p></p>
<p class=MsoPlainText> long start = System.nanoTime();<o:p></o:p></p>
<p class=MsoPlainText> for (int i = 0; i < loop; i++) {<o:p></o:p></p>
<p class=MsoPlainText> logbacklogger.debug("SEE IF THIS IS LOGGED
" + j + ".");<o:p></o:p></p>
<p class=MsoPlainText> }<o:p></o:p></p>
<p class=MsoPlainText> return (System.nanoTime() - start) / loop;<o:p></o:p></p>
<p class=MsoPlainText> }<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText> private static long logbackTestedDebugCall() {<o:p></o:p></p>
<p class=MsoPlainText> Integer j = new Integer(2);<o:p></o:p></p>
<p class=MsoPlainText> long start = System.nanoTime();<o:p></o:p></p>
<p class=MsoPlainText> for (int i = 0; i < loop; i++) {<o:p></o:p></p>
<p class=MsoPlainText> if (logbacklogger.isDebugEnabled())<o:p></o:p></p>
<p class=MsoPlainText> logbacklogger.debug("SEE IF THIS IS LOGGED
" + j + ".");<o:p></o:p></p>
<p class=MsoPlainText> }<o:p></o:p></p>
<p class=MsoPlainText> return (System.nanoTime() - start) / loop;<o:p></o:p></p>
<p class=MsoPlainText> }<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText> private static long logbackParametrizedDebugCall() {<o:p></o:p></p>
<p class=MsoPlainText> Integer j = new Integer(2);<o:p></o:p></p>
<p class=MsoPlainText> long start = System.nanoTime();<o:p></o:p></p>
<p class=MsoPlainText> for (int i = 0; i < loop; i++) {<o:p></o:p></p>
<p class=MsoPlainText> logbacklogger.debug("SEE IF THIS IS LOGGED
{}.", j);<o:p></o:p></p>
<p class=MsoPlainText> }<o:p></o:p></p>
<p class=MsoPlainText> return (System.nanoTime() - start) / loop;<o:p></o:p></p>
<p class=MsoPlainText> }<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText> private static void initConfig() {<o:p></o:p></p>
<p class=MsoPlainText> org.apache.log4j.Logger log4jRoot =
org.apache.log4j.Logger.getRootLogger();<o:p></o:p></p>
<p class=MsoPlainText> log4jRoot.setLevel(org.apache.log4j.Level.INFO);<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText> ch.qos.logback.classic.Logger lbRoot =
(ch.qos.logback.classic.Logger) LoggerFactory<o:p></o:p></p>
<p class=MsoPlainText> .getLogger("ROOT");<o:p></o:p></p>
<p class=MsoPlainText> lbRoot.setLevel(ch.qos.logback.classic.Level.INFO);<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText> // create the loggers<o:p></o:p></p>
<p class=MsoPlainText>
org.apache.log4j.Logger.getLogger("perfTest");<o:p></o:p></p>
<p class=MsoPlainText>
org.apache.log4j.Logger.getLogger("perfTest.ch");<o:p></o:p></p>
<p class=MsoPlainText>
org.apache.log4j.Logger.getLogger("perfTest.ch.qos");<o:p></o:p></p>
<p class=MsoPlainText>
org.apache.log4j.Logger.getLogger("perfTest.ch.qos.logback");<o:p></o:p></p>
<p class=MsoPlainText> LoggerFactory.getLogger("perfTest");<o:p></o:p></p>
<p class=MsoPlainText> LoggerFactory.getLogger("perfTest.ch");<o:p></o:p></p>
<p class=MsoPlainText>
LoggerFactory.getLogger("perfTest.ch.qos");<o:p></o:p></p>
<p class=MsoPlainText>
LoggerFactory.getLogger("perfTest.ch.qos.logback");<o:p></o:p></p>
<p class=MsoPlainText> }<o:p></o:p></p>
<p class=MsoPlainText>}<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>-- <o:p></o:p></p>
<p class=MsoPlainText>Sébastien Pennec<o:p></o:p></p>
<p class=MsoPlainText>sebastien@qos.ch<o:p></o:p></p>
<p class=MsoPlainText><o:p> </o:p></p>
<p class=MsoPlainText>Logback: The reliable, generic, fast and flexible logging
framework for Java.<o:p></o:p></p>
<p class=MsoPlainText>http://logback.qos.ch/<o:p></o:p></p>
<p class=MsoPlainText>_______________________________________________<o:p></o:p></p>
<p class=MsoPlainText>Logback-user mailing list<o:p></o:p></p>
<p class=MsoPlainText>Logback-user@qos.ch<o:p></o:p></p>
<p class=MsoPlainText>http://qos.ch/mailman/listinfo/logback-user<o:p></o:p></p>
</div>
<pre>*************************************************************************
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.
*************************************************************************
</pre></body>
</html>