[logback-dev] Logback initialization time analysis

[Phil Clay]

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
-------------- next part --------------
A non-text attachment was scrubbed...
Name: results.png
Type: image/png
Size: 11625 bytes
Desc: not available
URL: <http://mailman.qos.ch/pipermail/logback-dev/attachments/20111117/52355d24/attachment-0001.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 1_Loader.diff
Type: application/octet-stream
Size: 2335 bytes
Desc: not available
URL: <http://mailman.qos.ch/pipermail/logback-dev/attachments/20111117/52355d24/attachment-0004.obj>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 2_ContextBase.diff
Type: application/octet-stream
Size: 1293 bytes
Desc: not available
URL: <http://mailman.qos.ch/pipermail/logback-dev/attachments/20111117/52355d24/attachment-0005.obj>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 3_PatternLayout.diff
Type: application/octet-stream
Size: 11238 bytes
Desc: not available
URL: <http://mailman.qos.ch/pipermail/logback-dev/attachments/20111117/52355d24/attachment-0006.obj>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 4_ContextInitializer.diff
Type: application/octet-stream
Size: 4205 bytes
Desc: not available
URL: <http://mailman.qos.ch/pipermail/logback-dev/attachments/20111117/52355d24/attachment-0007.obj>