[logback-dev] Logback initialization time analysis
Joern Huxhorn
jhuxhorn at googlemail.com
Sat Nov 19 13:09:37 CET 2011
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
More information about the logback-dev
mailing list