Logback initialization time analysis
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
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
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@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
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@googlemail.com> To: logback developers list <logback-dev@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@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
_______________________________________________ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
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@googlemail.com> To: logback developers list <logback-dev@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@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
_______________________________________________ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
_______________________________________________ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
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@apache.org> To: logback developers list <logback-dev@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@googlemail.com> To: logback developers list <logback-dev@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@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
_______________________________________________ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
_______________________________________________ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
_______________________________________________ logback-dev mailing list logback-dev@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-dev
participants (4)
-
Ceki Gulcu -
Joern Huxhorn -
Phil Clay -
Ralph Goers