[logback-dev] Logback initialization time analysis
Phil Clay
pilf_b at yahoo.com
Tue Nov 22 20:33:31 CET 2011
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 <rgoers at apache.org>
To: logback developers list <logback-dev at qos.ch>
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 <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
_______________________________________________
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/20111122/dd3b8cd9/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: sample
Type: application/octet-stream
Size: 418 bytes
Desc: not available
URL: <http://mailman.qos.ch/pipermail/logback-dev/attachments/20111122/dd3b8cd9/attachment-0001.obj>
More information about the logback-dev
mailing list