The java source for LoggerInitTestis in the original email below.
The bash script that I used to test it is VERY basic. Throw away type stuff... but I've attached it to this email. Execute it like this: ./sample java -classpath logback-classic-<version>.jar:logback-core-<version>.jar:slf4j-api-1.6.0.jar:. LoggerInitTest It will print out the timings like this (yes, I know it's ugly, but it's quick and dirty): Min Max Average: 0.136 0.179 0.14399 ________________________________ From: Ralph Goers <[email protected]> To: logback developers list <[email protected]> Sent: Monday, November 21, 2011 5:54 PM Subject: Re: [logback-dev] Logback initialization time analysis 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
sample
Description: Binary data
_______________________________________________ logback-dev mailing list [email protected] http://mailman.qos.ch/mailman/listinfo/logback-dev
