[ http://jira.qos.ch/browse/LBCLASSIC-300?page=com.atlassian.jira.plugin.syste... ] Phil updated LBCLASSIC-300: --------------------------- Attachment: CliTest.txt CPU tracing output from yourkit profiler. This shows the timings of logback initialization methods that I'm seeing. In particular, take a look at: ch.qos.logback.classic.util.ContextInitializer.autoConfig()

Add ability to manually specify configuration BEFORE autoconfiguration ----------------------------------------------------------------------

Key: LBCLASSIC-300 URL: http://jira.qos.ch/browse/LBCLASSIC-300 Project: logback-classic Issue Type: Improvement Affects Versions: 0.9.29 Reporter: Phil Assignee: Logback dev list Priority: Minor Attachments: CliTest.txt

In order to make logback initialization faster, I would like the ability to programmatically configure logback and avoid the logic that happens in ContextInitializer.autoConfig(). Specifically, refer to this stack that occurs when getILoggerFactory() is initially called... ch.qos.logback.classic.util.ContextInitializer.autoConfig() line: 147 org.slf4j.impl.StaticLoggerBinder.init() line: 85 org.slf4j.impl.StaticLoggerBinder.<clinit>() line: 55 org.slf4j.LoggerFactory.bind() line: 121 org.slf4j.LoggerFactory.performInitialization() line: 111 org.slf4j.LoggerFactory.getILoggerFactory() line: 268 Now, for some background... I am using logback for a fast executing CLI program. Right now, initializing logback dominates the execution time of my CLIs. For example... When I started with logback, I was using logback.xml. If one of my CLIs took 1.5 seconds to run, I would see that initializing logback was taking 1 of those seconds (I used the yourkit profiler to identify this). 66% of the execution time is unacceptable. So, I switched from using logback.xml to programatically configuring logback in Java with the following code.. {code} LoggerContext loggingContext = (LoggerContext) LoggerFactory.getILoggerFactory(); loggingContext.reset(); ... FileAppender<ILoggingEvent> fileAppender = new FileAppender<ILoggingEvent>(); ... Logger rootLogger = loggingContext.getLogger(Logger.ROOT_LOGGER_NAME); rootLogger.addAppender(fileAppender); {code} This reduced the initialization time quite a bit. Now logback initialization is taking about .3 seconds. This is much better. However, I still think this can be improved by completely skipping the auto config logic. The initial call to LoggerFactory.getILoggerFactory() will attempt to auto configure logback.... which searches for groovy files, xml files, and falls back to BasicConfigurator. I don't need this auto configuration logic, since I am just going reset it and configure it myself anyway. I would like the ability to programmatically configure logback and totally avoid this auto configuration. Ideally I would be able to construct a LoggerContext instance, or the root Logger, or something. Then allow slf4j to bind to it without going through the auto config steps.

-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

[ http://jira.qos.ch/browse/LBCLASSIC-300?page=com.atlassian.jira.plugin.syste... ] Phil commented on LBCLASSIC-300: -------------------------------- I would like to contribute a patch to fix this. Before I start work, I would like your opinion on the following approach: Modify ContextInitializer.autoConfig() as follows: - Prior to calling findURLOfDefaultConfigurationFile, read a system property "logback.configurationClass" that contains the name of the class to use to perform the configuration. - If the configurationClass is defined, invoke the static configure method of the given class with this.loggerContext, then return. - else continue with the existing logic in autoConfig() The configuration class must contain a method with the following signature: public static void configure(LoggerContext lc); This follows the same pattern used by BasicConfigurator. Alternatively, I could 1) create an LoggingConfigurator interface with a configure(LoggerContext lc) method, 2) enforce that the configurationClass implements LoggingConfigurator 3) Instantiate an object of type configurationClass using a default constructor, and invoke the configure method 4) Make BasicConfigurator implement LoggingConfigurator (and follow the same pattern for invoking it) Thoughts?

Add ability to manually specify configuration BEFORE autoconfiguration ----------------------------------------------------------------------

Key: LBCLASSIC-300 URL: http://jira.qos.ch/browse/LBCLASSIC-300 Project: logback-classic Issue Type: Improvement Affects Versions: 0.9.29 Reporter: Phil Assignee: Logback dev list Priority: Minor Attachments: CliTest.java, CliTest.txt

In order to make logback initialization faster, I would like the ability to programmatically configure logback and avoid the logic that happens in ContextInitializer.autoConfig(). Specifically, refer to this stack that occurs when getILoggerFactory() is initially called... ch.qos.logback.classic.util.ContextInitializer.autoConfig() line: 147 org.slf4j.impl.StaticLoggerBinder.init() line: 85 org.slf4j.impl.StaticLoggerBinder.<clinit>() line: 55 org.slf4j.LoggerFactory.bind() line: 121 org.slf4j.LoggerFactory.performInitialization() line: 111 org.slf4j.LoggerFactory.getILoggerFactory() line: 268 Now, for some background... I am using logback for a fast executing CLI program. Right now, initializing logback dominates the execution time of my CLIs. For example... When I started with logback, I was using logback.xml. If one of my CLIs took 1.5 seconds to run, I would see that initializing logback was taking 1 of those seconds (I used the yourkit profiler to identify this). 66% of the execution time is unacceptable. So, I switched from using logback.xml to programatically configuring logback in Java with the following code.. {code} LoggerContext loggingContext = (LoggerContext) LoggerFactory.getILoggerFactory(); loggingContext.reset(); ... FileAppender<ILoggingEvent> fileAppender = new FileAppender<ILoggingEvent>(); ... Logger rootLogger = loggingContext.getLogger(Logger.ROOT_LOGGER_NAME); rootLogger.addAppender(fileAppender); {code} This reduced the initialization time quite a bit. Now logback initialization is taking about .3 seconds. This is much better. However, I still think this can be improved by completely skipping the auto config logic. The initial call to LoggerFactory.getILoggerFactory() will attempt to auto configure logback.... which searches for groovy files, xml files, and falls back to BasicConfigurator. I don't need this auto configuration logic, since I am just going reset it and configure it myself anyway. I would like the ability to programmatically configure logback and totally avoid this auto configuration. Ideally I would be able to construct a LoggerContext instance, or the root Logger, or something. Then allow slf4j to bind to it without going through the auto config steps.

-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

[ http://jira.qos.ch/browse/LBCLASSIC-300?page=com.atlassian.jira.plugin.syste... ] Phil commented on LBCLASSIC-300: -------------------------------- That is an excellent point, Ceki. I will definitely profile the changes prior to submitting the patch. If the changes don't result in any performance increase, then I will close this issue, as there is no point. In the meantime, I compared logback-classic (using BasicConfigurator, no xml) against slf4j-nop. I created a simple class with the following main method: public static void main(String[] args) { LoggerFactory.getILoggerFactory(); } I ran that class 200 times each from the CLI. Here are the aggregated results: logback-classic using BasicConfigurator (no xml): Min Max Average: 0.346 0.415 0.358446 slf4j-nop: Min Max Average: 0.195 0.408 0.212901 Looking at the mins and avgs, logback has about a 70% increase in initialization costs over slf4j-nop. I don't know exactly how much my proposed change will decrease the initialization costs, but it's definitely worth investigating to me.

Add ability to manually specify configuration BEFORE autoconfiguration ----------------------------------------------------------------------

Key: LBCLASSIC-300 URL: http://jira.qos.ch/browse/LBCLASSIC-300 Project: logback-classic Issue Type: Improvement Affects Versions: 0.9.29 Reporter: Phil Assignee: Logback dev list Priority: Minor Attachments: CliTest.java, CliTest.txt

In order to make logback initialization faster, I would like the ability to programmatically configure logback and avoid the logic that happens in ContextInitializer.autoConfig(). Specifically, refer to this stack that occurs when getILoggerFactory() is initially called... ch.qos.logback.classic.util.ContextInitializer.autoConfig() line: 147 org.slf4j.impl.StaticLoggerBinder.init() line: 85 org.slf4j.impl.StaticLoggerBinder.<clinit>() line: 55 org.slf4j.LoggerFactory.bind() line: 121 org.slf4j.LoggerFactory.performInitialization() line: 111 org.slf4j.LoggerFactory.getILoggerFactory() line: 268 Now, for some background... I am using logback for a fast executing CLI program. Right now, initializing logback dominates the execution time of my CLIs. For example... When I started with logback, I was using logback.xml. If one of my CLIs took 1.5 seconds to run, I would see that initializing logback was taking 1 of those seconds (I used the yourkit profiler to identify this). 66% of the execution time is unacceptable. So, I switched from using logback.xml to programatically configuring logback in Java with the following code.. {code} LoggerContext loggingContext = (LoggerContext) LoggerFactory.getILoggerFactory(); loggingContext.reset(); ... FileAppender<ILoggingEvent> fileAppender = new FileAppender<ILoggingEvent>(); ... Logger rootLogger = loggingContext.getLogger(Logger.ROOT_LOGGER_NAME); rootLogger.addAppender(fileAppender); {code} This reduced the initialization time quite a bit. Now logback initialization is taking about .3 seconds. This is much better. However, I still think this can be improved by completely skipping the auto config logic. The initial call to LoggerFactory.getILoggerFactory() will attempt to auto configure logback.... which searches for groovy files, xml files, and falls back to BasicConfigurator. I don't need this auto configuration logic, since I am just going reset it and configure it myself anyway. I would like the ability to programmatically configure logback and totally avoid this auto configuration. Ideally I would be able to construct a LoggerContext instance, or the root Logger, or something. Then allow slf4j to bind to it without going through the auto config steps.

-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

[ http://jira.qos.ch/browse/LBCLASSIC-300?page=com.atlassian.jira.plugin.syste... ] Phil commented on LBCLASSIC-300: -------------------------------- After implementing this fix (see diff attached to this report), performance analysis shows that there was no significant speed increase. See analysis sent to the dev mailing list... http://mailman.qos.ch/pipermail/logback-dev/2011-November/006915.html This is most likely caused by the fact that classloading and static initialization dominates the initialization costs, and very few classes are avoided being loaded with this fix. My recommendation is for this issue to be closed without applying the diff.

Add ability to manually specify configuration BEFORE autoconfiguration ----------------------------------------------------------------------

Key: LBCLASSIC-300 URL: http://jira.qos.ch/browse/LBCLASSIC-300 Project: logback-classic Issue Type: Improvement Affects Versions: 0.9.29 Reporter: Phil Assignee: Logback dev list Priority: Minor Attachments: 4_ContextInitializer.diff, CliTest.java, CliTest.txt

In order to make logback initialization faster, I would like the ability to programmatically configure logback and avoid the logic that happens in ContextInitializer.autoConfig(). Specifically, refer to this stack that occurs when getILoggerFactory() is initially called... ch.qos.logback.classic.util.ContextInitializer.autoConfig() line: 147 org.slf4j.impl.StaticLoggerBinder.init() line: 85 org.slf4j.impl.StaticLoggerBinder.<clinit>() line: 55 org.slf4j.LoggerFactory.bind() line: 121 org.slf4j.LoggerFactory.performInitialization() line: 111 org.slf4j.LoggerFactory.getILoggerFactory() line: 268 Now, for some background... I am using logback for a fast executing CLI program. Right now, initializing logback dominates the execution time of my CLIs. For example... When I started with logback, I was using logback.xml. If one of my CLIs took 1.5 seconds to run, I would see that initializing logback was taking 1 of those seconds (I used the yourkit profiler to identify this). 66% of the execution time is unacceptable. So, I switched from using logback.xml to programatically configuring logback in Java with the following code.. {code} LoggerContext loggingContext = (LoggerContext) LoggerFactory.getILoggerFactory(); loggingContext.reset(); ... FileAppender<ILoggingEvent> fileAppender = new FileAppender<ILoggingEvent>(); ... Logger rootLogger = loggingContext.getLogger(Logger.ROOT_LOGGER_NAME); rootLogger.addAppender(fileAppender); {code} This reduced the initialization time quite a bit. Now logback initialization is taking about .3 seconds. This is much better. However, I still think this can be improved by completely skipping the auto config logic. The initial call to LoggerFactory.getILoggerFactory() will attempt to auto configure logback.... which searches for groovy files, xml files, and falls back to BasicConfigurator. I don't need this auto configuration logic, since I am just going reset it and configure it myself anyway. I would like the ability to programmatically configure logback and totally avoid this auto configuration. Ideally I would be able to construct a LoggerContext instance, or the root Logger, or something. Then allow slf4j to bind to it without going through the auto config steps.

-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira