[logback-dev] Logback initialization time analysis
Ralph Goers
rgoers at apache.org
Mon Nov 21 23:54:11 CET 2011
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 <jhuxhorn at googlemail.com>
> To: logback developers list <logback-dev at qos.ch>
> 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
> > logback-dev at qos.ch
> > http://mailman.qos.ch/mailman/listinfo/logback-dev
>
> _______________________________________________
> logback-dev mailing list
> logback-dev at qos.ch
> http://mailman.qos.ch/mailman/listinfo/logback-dev
>
>
> _______________________________________________
> logback-dev mailing list
> logback-dev at qos.ch
> http://mailman.qos.ch/mailman/listinfo/logback-dev
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-dev/attachments/20111121/959e95b7/attachment-0001.html>
More information about the logback-dev
mailing list