<html><head></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space; ">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="Apple-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 href="mailto:jhuxhorn@googlemail.com">jhuxhorn@googlemail.com</a>><br> <b><span style="font-weight: bold;">To:</span></b> logback developers list
<<a 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 href="https://github.com/ceki/logback/tree/LBCLASSIC-304" target="_blank">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 <a href="http://jira.qos.ch/browse/LBCLASSIC-300">http://jira.qos.ch/browse/LBCLASSIC-300</a> 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 href="http://jira.qos.ch/browse/LBCLASSIC-300" target="_blank">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 href="http://jira.qos.ch/browse/LBCLASSIC-263" target="_blank">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 href="http://jira.qos.ch/browse/LBCLASSIC-300" target="_blank">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 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">http://mailman.qos.ch/mailman/listinfo/logback-dev</a><br><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><br> </div> </div> </div></div>_______________________________________________<br>logback-dev mailing list<br><a href="mailto:logback-dev@qos.ch">logback-dev@qos.ch</a><br>http://mailman.qos.ch/mailman/listinfo/logback-dev</blockquote></div><br></div></body></html>