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
