<html><body><div style="color:#000; background-color:#fff; font-family:Courier New, courier, monaco, monospace, sans-serif;font-size:12pt"><div style="font-family: arial,helvetica,sans-serif;"><span>The java source for </span>LoggerInitTest<span> is in the original email below.<br></span></div><div style="font-family: arial,helvetica,sans-serif;"><span><br></span></div><div style="font-family: arial,helvetica,sans-serif;"><span>The bash script that I used to test it is VERY basic. Throw away type stuff... but I've attached it to this email.<br></span></div><div style="font-family: arial,helvetica,sans-serif;"><br><span></span></div><div style="font-family: arial,helvetica,sans-serif;">Execute it like this:</div><div style="font-family: arial,helvetica,sans-serif;"><br></div><div style="font-family: arial,helvetica,sans-serif;">./sample java -classpath logback-classic-<version>.jar:logback-core-<version>.jar:slf4j-api-1.6.0.jar:.
LoggerInitTest</div><div style="font-family: arial,helvetica,sans-serif;"><br></div><div style="font-family: arial,helvetica,sans-serif;"><br></div><div style="font-family: arial,helvetica,sans-serif;">It will print out the timings like this (yes, I know it's ugly, but it's quick and dirty):</div><div style="font-family: arial,helvetica,sans-serif;"><br></div><div style="font-family: arial,helvetica,sans-serif;">Min Max Average:<br>0.136 0.179 0.14399<br><br></div><div style="font-family: arial,helvetica,sans-serif;"><br><span></span></div><div style="font-family: arial,helvetica,sans-serif;"><br><span></span></div><div><span></span></div><div><br></div><div style="font-family: Courier New, courier, monaco, monospace, sans-serif; font-size: 12pt;"><div style="font-family: times new roman, new york, times, serif; font-size: 12pt;"><font face="Arial" size="2"><hr size="1"><b><span style="font-weight:bold;">From:</span></b> Ralph Goers
<rgoers@apache.org><br><b><span style="font-weight: bold;">To:</span></b> logback developers list <logback-dev@qos.ch><br><b><span style="font-weight: bold;">Sent:</span></b> Monday, November 21, 2011 5:54 PM<br><b><span style="font-weight: bold;">Subject:</span></b> Re: [logback-dev] Logback initialization time analysis<br></font><br>
<meta http-equiv="x-dns-prefetch-control" content="off"><div id="yiv284330993"><div>Did you publish your test source somewhere?<div><br></div><div>Ralph</div><div><br><div><div>On Nov 21, 2011, at 1:55 PM, Phil Clay wrote:</div><br class="yiv284330993Apple-interchange-newline"><blockquote type="cite"><div><div style="color:#000;background-color:#fff;font-family:arial, helvetica, sans-serif;font-size:12pt;"><div><span>Hi Joern,</span></div><div><br><span></span></div><div><span>I tested out the LBCLASSIC-304 branch today. The initialization performance seems to be on-par with 0.9.29 (and also 1.0.1 plus the previous diff #1 from below applied).</span></div><div><br><span></span></div><div><span>I didn't test for functionality, just initialization performance.</span></div><div><br><span></span></div><div><span>Phil</span></div><div><br></div> <div style="font-family:arial, helvetica, sans-serif;font-size:12pt;"> <div style="font-family:times new
roman, new york, times, serif;font-size:12pt;"> <font face="Arial" size="2"> <hr size="1"> <b><span style="font-weight:bold;">From:</span></b> Joern Huxhorn <<a rel="nofollow" ymailto="mailto:jhuxhorn@googlemail.com" target="_blank" href="mailto:jhuxhorn@googlemail.com">jhuxhorn@googlemail.com</a>><br> <b><span style="font-weight:bold;">To:</span></b> logback developers list
<<a rel="nofollow" ymailto="mailto:logback-dev@qos.ch" target="_blank" href="mailto:logback-dev@qos.ch">logback-dev@qos.ch</a>> <br> <b><span style="font-weight:bold;">Sent:</span></b> Saturday, November 19, 2011 7:09 AM<br> <b><span style="font-weight:bold;">Subject:</span></b> Re: [logback-dev] Logback initialization time analysis<br> </font> <br>
Hi Phil,<br><br>could you check how <a rel="nofollow" target="_blank" href="https://github.com/ceki/logback/tree/LBCLASSIC-304">https://github.com/ceki/logback/tree/LBCLASSIC-304</a> performs? The static initialization is wrong, anyway, as is lazy initialization, since HAS_GET_CLASS_LOADER_PERMISSION can change per thread.<br><br>Unfortunately, I haven't yet been able to create a test project to validate that everything is working as expected with my changes...<br><br>Cheers,<br>Joern.<br><br>On 18.11.2011, at 07:15, Ceki Gulcu wrote:<br><br>> <br>> Hi Phil,<br>> <br>> Thank you for this great analysis. I am currently on vacation and thus<br>> can't give your post the attention it deserves. However, I'll be back<br>> later next week (24th) at which time will study your recommendations<br>> carefully. Joern may comment or already implement your changes in the<br>> mean time.<br>> <br>> Cheers,<br>> <br>> On 17.11.2011
22:16, Phil Clay
wrote:<br>>> <br>>> <br>>> In an effort to speed up a CLI program that uses slf4j and logback, I've done some analysis on logback initialization time.<br>>> <br>>> This came about because logback initialization was dominating our CLI execution time. Mainly this was because of XML configuration. Therefore, in our CLIs, I have replaced XML configuration with programmatic configuration in java. This reduced the logback initialization overhead drastically. But I wanted to analyze this further to see if more enhancements could be made.<br>>> <br>>> With the yourkit profiler, I identified several 'hotspots' in the code and made various tweeks to remove those hotspots. I measured each change individually to see what kind of benefit (if any) it gave.<br>>> <br>>> Skip down to the CONCLUSION if you don't care about the details.<br>>> <br>>> <br>>> == TEST SETUP
==<br>>> <br>>> I created a class as follows:<br>>> <br>>> public class LoggerInitTest {<br>>> public static void main(String[] args) {<br>>> LoggerFactory.getILoggerFactory();<br>>> }<br>>> }<br>>> <br>>> <br>>> No xml or grovy configuration files exist on the classpath. XML/groovy configuration is expensive. We get the greatest benefit by just not using it, so I didn't bother trying to speed it up.<br>>> <br>>> <br>>> == TEST EXECUTION ==<br>>> <br>>> Each case below was executed 200 times from the cli. (i.e. the loop was in bash, not java).<br>>> <br>>> The min/max/avg times were calculated for each case.<br>>> <br>>> <br>>> <br>>> == TEST CASE A ==<br>>> <br>>> Baseline test case using slf4j-nop instead of logback.<br>>>
<br>>> <br>>> <br>>> == TEST CASE B ==<br>>> <br>>> logback 0.9.29 (unmodified)<br>>> <br>>> <br>>> <br>>> == TEST CASE C ==<br>>> <br>>> logback 1.0.1 (unmodified) Git cloned last week. Don't have the exact change number in front of me...<br>>> <br>>> <br>>> <br>>> == TEST CASE D ==<br>>> <br>>> logback 1.0.1 with the following modification<br>>> 1) Loader.HAS_GET_CLASS_LOADER_PERMISSION converted to be lazily initialized<br>>> <br>>> See attached 1_Loader.diff<br>>> <br>>> <br>>> Classloading the Loader class was identified as a hotspot because of static initialization. By lazily loading HAS_GET_CLASS_LOADER_PERMISSION, we can avoid the performance hit unless it is needed. In my CLIs, HAS_GET_CLASS_LOADER_PERMISSION is never needed, therefore the initialization cost is completely
avoided.<br>>> <br>>> <br>>> <br>>> == TEST CASE E ==<br>>> <br>>> logback 1.0.1 with the following modifications<br>>> 1) (from above)<br>>> 2) ContextBase.executorService converted to be lazily initialized<br>>> <br>>> See attached 2_ContextBase.diff<br>>> <br>>> Initializing the executorService was identified as a hotspot. By lazily loading executorService, we can avoid the performance hit unless it is needed. In my tests, executorService is never needed.<br>>> <br>>> <br>>> <br>>> == TEST CASE F ==<br>>> <br>>> logback 1.0.1 with the following modifications<br>>> 1) (from above)<br>>> 2) (from above)<br>>> 3) PatternLayout.defaultConverterMap classes lazily loaded<br>>> <br>>> See attached 3_PatternLayout.diff<br>>> <br>>> Since the classnames are populated in the defaultConverterMap by
statically referencing the class, and calling getName(). For example:<br>>> <br>>> ch.qos.logback.classic.pattern.DateConverter.class.getName();<br>>> <br>>> This causes all of the converter classes to be loaded, even if they are not used.<br>>> <br>>> I converted the classnames to be string literals instead. For example:<br>>> <br>>> "ch.qos.logback.classic.pattern.DateConverter"<br>>> <br>>> This allows the converter classes to not be loaded until/unless they are actually used. I don't need many of the converters.<br>>> <br>>> The downside of this change is that you lose compile-time safety on the class names.<br>>> <br>>> <br>>> <br>>> == TEST CASE G ==<br>>> <br>>> logback 1.0.1 with the following modifications<br>>> 1) (from above)<br>>> 2) (from above)<br>>> 3) (from
above)<br>>> <br>>> Also,<br>>> <br>>> The LoggerInitTest class was modified to perform additional configuration beyond BasicConfigurator<br>>> <br>>> <br>>> This test case is to provide a baseline to see if the change proposed in http://jira.qos.ch/browse/LBCLASSIC-300 has any benefit.<br>>> <br>>> <br>>> <br>>> == TEST CASE H ==<br>>> <br>>> logback 1.0.1 with the following modifications<br>>> 1) (from above)<br>>> 2) (from above)<br>>> 3) (from above)<br>>> 4) ContextInitializer changed to allow configuration by java class (and skip configuration file lookup and BasicConfigurator logic).<br>>> <br>>> See attached 4_ContextInitializer.diff<br>>> <br>>> The LoggerInitTest class was modified to provide LoggerContext configuration (via hook into #4). Therefore the logic to search the classpath for XML/groovy files and the
configuration logic in BasicConfigurator was avoided.<br>>> <br>>> The results of this test case can be compared against test case #G to see if the change proposed in <a rel="nofollow" target="_blank" href="http://jira.qos.ch/browse/LBCLASSIC-300">http://jira.qos.ch/browse/LBCLASSIC-300</a> has any benefit.<br>>> <br>>> <br>>> <br>>> == TEST RESULTS ==<br>>> <br>>> Numbers are in milliseconds.<br>>> <br>>> Case min max avg<br>>> A 131 247 165<br>>> B 281 496 293<br>>> C 331 546 347<br>>> D 282 499 296<br>>> E 281 496 292<br>>> F 280 450
287<br>>> G 282 492 307<br>>> H 282 450 300<br>>> <br>>> See this in graph form in attached results.png<br>>> <br>>> <br>>> <br>>> == ANALYSIS ==<br>>> <br>>> Initialization time increased significantly between (B) 0.9.29 and (C) the current 1.0.1 head.<br>>> <br>>> After change #1 from (D) was made, performance was back on-par with 0.9.29. I identified that the HAS_GET_CLASS_LOADER_PERMISSION was introduced after 0.9.29 (<a rel="nofollow" target="_blank" href="http://jira.qos.ch/browse/LBCLASSIC-263">http://jira.qos.ch/browse/LBCLASSIC-263</a>), so this is further evidence that this caused the increase seen in (C).<br>>> <br>>> None of the other changes from E, F, G, or H, had any noticable impact to initialization performance. When profiling with yourkit, I can
see the
performance difference. But, when executing the test without profiling, no change can be seen.<br>>> <br>>> <br>>> I was unable to make any changes that decreased initialization time below that of (B) 0.9.29.<br>>> <br>>> After further profiling of individual tests runs with yourkit, I can see that most of the initialization time is spent in the following areas:<br>>> - classloading (mainly because of static initialization)<br>>> - Pattern compiling / parsing<br>>> <br>>> I could not identify any other places to reduce the number of classes loaded by logback.<br>>> <br>>> <br>>> == CONCLUSION ==<br>>> <br>>> The only change that I can recommend incorporating into logback to decrease initialization time is from test case (D):<br>>> 1) Loader.HAS_GET_CLASS_LOADER_PERMISSION converted to be lazily initialized<br>>> <br>>> See attached
1_Loader.diff<br>>> <br>>> This would get initialization time of 1.0.1 back down to the initialization time of (B) 0.9.29.<br>>> <br>>> <br>>> == ACTION ITEMS ==<br>>> <br>>> I'll file a JIRA issue for incorporating change #1 into logback.<br>>> <br>>> I'm going to close <a rel="nofollow" target="_blank" href="http://jira.qos.ch/browse/LBCLASSIC-300">http://jira.qos.ch/browse/LBCLASSIC-300</a> (filed by me) because the proposed change had no impact to initialization performance.<br>>> <br>>> If you have any other suggestions on ways to improve initialization performance, please let me know. Other thoughts are welcome as well.<br>>> <br>>> <br>>> Thanks,<br>>> <br>>> Phil<br>> <br>> <br>> _______________________________________________<br>> logback-dev mailing list<br>> <a rel="nofollow" ymailto="mailto:logback-dev@qos.ch" target="_blank"
href="mailto:logback-dev@qos.ch">logback-dev@qos.ch</a><br>> http://mailman.qos.ch/mailman/listinfo/logback-dev<br><br>_______________________________________________<br>logback-dev mailing list<br><a rel="nofollow" ymailto="mailto:logback-dev@qos.ch" target="_blank" href="mailto:logback-dev@qos.ch">logback-dev@qos.ch</a><br><a rel="nofollow" target="_blank" href="http://mailman.qos.ch/mailman/listinfo/logback-dev">http://mailman.qos.ch/mailman/listinfo/logback-dev</a><br><br><br> </div> </div> </div></div>_______________________________________________<br>logback-dev mailing list<br><a rel="nofollow" ymailto="mailto:logback-dev@qos.ch" target="_blank" href="mailto:logback-dev@qos.ch">logback-dev@qos.ch</a><br>http://mailman.qos.ch/mailman/listinfo/logback-dev</blockquote></div><br></div></div></div><meta http-equiv="x-dns-prefetch-control" content="on"><br>_______________________________________________<br>logback-dev mailing list<br><a
ymailto="mailto:logback-dev@qos.ch" href="mailto:logback-dev@qos.ch">logback-dev@qos.ch</a><br><a href="http://mailman.qos.ch/mailman/listinfo/logback-dev" target="_blank">http://mailman.qos.ch/mailman/listinfo/logback-dev</a><br><br></div></div></div></body></html>