Did you publish your test source somewhere? Ralph
On Nov 21, 2011, at 1:55 PM, Phil Clay wrote: > Hi Joern, > > 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). > > I didn't test for functionality, just initialization performance. > > Phil > > From: Joern Huxhorn <[email protected]> > To: logback developers list <[email protected]> > Sent: Saturday, November 19, 2011 7:09 AM > Subject: Re: [logback-dev] Logback initialization time analysis > > Hi Phil, > > could you check how https://github.com/ceki/logback/tree/LBCLASSIC-304 > performs? The static initialization is wrong, anyway, as is lazy > initialization, since HAS_GET_CLASS_LOADER_PERMISSION can change per thread. > > Unfortunately, I haven't yet been able to create a test project to validate > that everything is working as expected with my changes... > > Cheers, > Joern. > > On 18.11.2011, at 07:15, Ceki Gulcu wrote: > > > > > Hi Phil, > > > > Thank you for this great analysis. I am currently on vacation and thus > > can't give your post the attention it deserves. However, I'll be back > > later next week (24th) at which time will study your recommendations > > carefully. Joern may comment or already implement your changes in the > > mean time. > > > > Cheers, > > > > On 17.11.2011 22:16, Phil Clay wrote: > >> > >> > >> In an effort to speed up a CLI program that uses slf4j and logback, I've > >> done some analysis on logback initialization time. > >> > >> 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. > >> > >> 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. > >> > >> Skip down to the CONCLUSION if you don't care about the details. > >> > >> > >> == TEST SETUP == > >> > >> I created a class as follows: > >> > >> public class LoggerInitTest { > >> public static void main(String[] args) { > >> LoggerFactory.getILoggerFactory(); > >> } > >> } > >> > >> > >> 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. > >> > >> > >> == TEST EXECUTION == > >> > >> Each case below was executed 200 times from the cli. (i.e. the loop was > >> in bash, not java). > >> > >> The min/max/avg times were calculated for each case. > >> > >> > >> > >> == TEST CASE A == > >> > >> Baseline test case using slf4j-nop instead of logback. > >> > >> > >> > >> == TEST CASE B == > >> > >> logback 0.9.29 (unmodified) > >> > >> > >> > >> == TEST CASE C == > >> > >> logback 1.0.1 (unmodified) Git cloned last week. Don't have the exact > >> change number in front of me... > >> > >> > >> > >> == TEST CASE D == > >> > >> logback 1.0.1 with the following modification > >> 1) Loader.HAS_GET_CLASS_LOADER_PERMISSION converted to be lazily > >> initialized > >> > >> See attached 1_Loader.diff > >> > >> > >> 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. > >> > >> > >> > >> == TEST CASE E == > >> > >> logback 1.0.1 with the following modifications > >> 1) (from above) > >> 2) ContextBase.executorService converted to be lazily initialized > >> > >> See attached 2_ContextBase.diff > >> > >> 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. > >> > >> > >> > >> == TEST CASE F == > >> > >> logback 1.0.1 with the following modifications > >> 1) (from above) > >> 2) (from above) > >> 3) PatternLayout.defaultConverterMap classes lazily loaded > >> > >> See attached 3_PatternLayout.diff > >> > >> Since the classnames are populated in the defaultConverterMap by > >> statically referencing the class, and calling getName(). For example: > >> > >> ch.qos.logback.classic.pattern.DateConverter.class.getName(); > >> > >> This causes all of the converter classes to be loaded, even if they are > >> not used. > >> > >> I converted the classnames to be string literals instead. For example: > >> > >> "ch.qos.logback.classic.pattern.DateConverter" > >> > >> This allows the converter classes to not be loaded until/unless they are > >> actually used. I don't need many of the converters. > >> > >> The downside of this change is that you lose compile-time safety on the > >> class names. > >> > >> > >> > >> == TEST CASE G == > >> > >> logback 1.0.1 with the following modifications > >> 1) (from above) > >> 2) (from above) > >> 3) (from above) > >> > >> Also, > >> > >> The LoggerInitTest class was modified to perform additional configuration > >> beyond BasicConfigurator > >> > >> > >> 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. > >> > >> > >> > >> == TEST CASE H == > >> > >> logback 1.0.1 with the following modifications > >> 1) (from above) > >> 2) (from above) > >> 3) (from above) > >> 4) ContextInitializer changed to allow configuration by java class (and > >> skip configuration file lookup and BasicConfigurator logic). > >> > >> See attached 4_ContextInitializer.diff > >> > >> 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. > >> > >> The results of this test case can be compared against test case #G to see > >> if the change proposed in http://jira.qos.ch/browse/LBCLASSIC-300 has any > >> benefit. > >> > >> > >> > >> == TEST RESULTS == > >> > >> Numbers are in milliseconds. > >> > >> Case min max avg > >> A 131 247 165 > >> B 281 496 293 > >> C 331 546 347 > >> D 282 499 296 > >> E 281 496 292 > >> F 280 450 287 > >> G 282 492 307 > >> H 282 450 300 > >> > >> See this in graph form in attached results.png > >> > >> > >> > >> == ANALYSIS == > >> > >> Initialization time increased significantly between (B) 0.9.29 and (C) the > >> current 1.0.1 head. > >> > >> 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 (http://jira.qos.ch/browse/LBCLASSIC-263), so this > >> is further evidence that this caused the increase seen in (C). > >> > >> 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. > >> > >> > >> I was unable to make any changes that decreased initialization time below > >> that of (B) 0.9.29. > >> > >> After further profiling of individual tests runs with yourkit, I can see > >> that most of the initialization time is spent in the following areas: > >> - classloading (mainly because of static initialization) > >> - Pattern compiling / parsing > >> > >> I could not identify any other places to reduce the number of classes > >> loaded by logback. > >> > >> > >> == CONCLUSION == > >> > >> The only change that I can recommend incorporating into logback to > >> decrease initialization time is from test case (D): > >> 1) Loader.HAS_GET_CLASS_LOADER_PERMISSION converted to be lazily > >> initialized > >> > >> See attached 1_Loader.diff > >> > >> This would get initialization time of 1.0.1 back down to the > >> initialization time of (B) 0.9.29. > >> > >> > >> == ACTION ITEMS == > >> > >> I'll file a JIRA issue for incorporating change #1 into logback. > >> > >> I'm going to close http://jira.qos.ch/browse/LBCLASSIC-300 (filed by me) > >> because the proposed change had no impact to initialization performance. > >> > >> If you have any other suggestions on ways to improve initialization > >> performance, please let me know. Other thoughts are welcome as well. > >> > >> > >> Thanks, > >> > >> Phil > > > > > > _______________________________________________ > > logback-dev mailing list > > [email protected] > > http://mailman.qos.ch/mailman/listinfo/logback-dev > > _______________________________________________ > logback-dev mailing list > [email protected] > http://mailman.qos.ch/mailman/listinfo/logback-dev > > > _______________________________________________ > logback-dev mailing list > [email protected] > http://mailman.qos.ch/mailman/listinfo/logback-dev
_______________________________________________ logback-dev mailing list [email protected] http://mailman.qos.ch/mailman/listinfo/logback-dev
