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<<attachment: results.png>>
1_Loader.diff
Description: Binary data
2_ContextBase.diff
Description: Binary data
3_PatternLayout.diff
Description: Binary data
4_ContextInitializer.diff
Description: Binary data
_______________________________________________ logback-dev mailing list [email protected] http://mailman.qos.ch/mailman/listinfo/logback-dev
