Details

    • Type: Improvement
    • Status: Resolved
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 1.1.5
    • Fix Version/s: 1.1.6
    • Component/s: logback-classic
    • Labels:
      None

      Description

      From Ceki's Mar 3rd, 2014 comment on the Java Bien! blog:

      As for logback start up time, I think that resolving the local host name might be responsible for the delay more than the class load time. In any case, I agree that 200 ms to load the logback config file may be somewhat excessive.

      A few details about my application:

      • Without logback on the classpath, my application starts up in ~275ms.
      • With logback on the classpath—and without any configuration files—my application starts up in ~375ms.
      • With a logback.xml configuration on the classpath, my application starts up in ~450ms.

      So logback is adding between 100 and 175 ms of startup time, depending on whether there is a logback.xml file present. I can deal with the initial extra 100ms, but once startup time reaches the ~450ms mark, it creates a very noticeable lag. This is a command-line application intended to be run many times per day by users, so startup time really matters.

      I have not profiled the application to see where the hotspots actually lie, but if the hostname lookup is indeed a major contributor to the problem, perhaps it could be made optional.

      Otherwise, anything that can be done to reduce logback startup time to a minimum would be appreciated.

        Activity

        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited

        Chris Beams This issue is tougher than I expected. Some simple statements executed during logback initialization, e.g. loops on lists with 3 or 4 elements take 20 milliseconds, but would probably cost only a few nanoseconds later in the application lifecycle. Joran could be made to be quicker but that is not a simple undertaking.

        Another way to reduce logback's impact on application start up is to skip configuration using Joran (with a configuration file that needs to be looked up) and instead configure logback programmatically with a Configurator specified under META-INF/services/ch.qos.logback.classic.spi.Configurator.
        In a recent commit, I modified BasicConfigurator to conform to the the Configurator interface.

        Here is a very simple app to measure logback's impact on app start up time.

        public class Main {
            static public void main(String[] args) throws Exception {
                long start = System.nanoTime();
                Logger logger = LoggerFactory.getLogger("a");
                long end = System.nanoTime();
                long diff = (end-start)/1000/1000;
                System.out.print("elapsed time in milli-seconds "+diff);
            }
        }
        

        BasicConfigurator.configure runtime has been improved significantly by using a fixed format layout called TTLLLayout instead of PatternLayout. It turns out that parsing of the pattern string by PatternLayout takes up 30 milliseconds.

        Thus, programmatic initialization instead of using Joran cuts start up time from 206 milliseconds to 50 milliseconds.

        To enable BasicConfigurator, just add the line "ch.qos.logback.classic.BasicConfigurator" in the file META-INF/services/ch.qos.logback.classic.spi.Configurator. To enable another configurator you would add its fqcn in the aforementioned services file.

        Note if no config files were found on the class path nor and META-INF/services/ch.qos.logback.classic.spi.Configurator does not exists, logback will default to BasicConfigurator. As mentioned above, its execution has been improved.

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited Chris Beams This issue is tougher than I expected. Some simple statements executed during logback initialization, e.g. loops on lists with 3 or 4 elements take 20 milliseconds, but would probably cost only a few nanoseconds later in the application lifecycle. Joran could be made to be quicker but that is not a simple undertaking. Another way to reduce logback's impact on application start up is to skip configuration using Joran (with a configuration file that needs to be looked up) and instead configure logback programmatically with a Configurator specified under META-INF/services/ch.qos.logback.classic.spi.Configurator . In a recent commit , I modified BasicConfigurator to conform to the the Configurator interface. Here is a very simple app to measure logback's impact on app start up time. public class Main { static public void main( String [] args) throws Exception { long start = System .nanoTime(); Logger logger = LoggerFactory.getLogger( "a" ); long end = System .nanoTime(); long diff = (end-start)/1000/1000; System .out.print( "elapsed time in milli-seconds " +diff); } } BasicConfigurator.configure runtime has been improved significantly by using a fixed format layout called TTLLLayout instead of PatternLayout . It turns out that parsing of the pattern string by PatternLayout takes up 30 milliseconds. Thus, programmatic initialization instead of using Joran cuts start up time from 206 milliseconds to 50 milliseconds. To enable BasicConfigurator , just add the line "ch.qos.logback.classic.BasicConfigurator" in the file META-INF/services/ch.qos.logback.classic.spi.Configurator . To enable another configurator you would add its fqcn in the aforementioned services file. Note if no config files were found on the class path nor and META-INF/services/ch.qos.logback.classic.spi.Configurator does not exists, logback will default to BasicConfigurator . As mentioned above, its execution has been improved.
        Hide
        cbeams Chris Beams added a comment -

        Thanks, Ceki. I actually did take a shot at the ServiceLoader-based approach, but was unable to get it work. I'm well familiar with the mechanism; I'm not sure what was going wrong. I'll take another look when I have a moment.

        Thanks in any case for looking into this and getting back.

        Show
        cbeams Chris Beams added a comment - Thanks, Ceki. I actually did take a shot at the ServiceLoader -based approach, but was unable to get it work. I'm well familiar with the mechanism; I'm not sure what was going wrong. I'll take another look when I have a moment. Thanks in any case for looking into this and getting back.
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment -

        Removing all config files with nothing in META-INF/services/ch.qos.logback.classic.spi.Configurator, should result in logback defaulting to BasicConfigurator with total cost of logback to application start up time of approx. 50 milliseconds

        If you need a configuration other than that provided by BasicConfigurator, then write your own configurator possibly based on BasicConfigurator.

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - Removing all config files with nothing in META-INF/services/ch.qos.logback.classic.spi.Configurator, should result in logback defaulting to BasicConfigurator with total cost of logback to application start up time of approx. 50 milliseconds If you need a configuration other than that provided by BasicConfigurator, then write your own configurator possibly based on BasicConfigurator.
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment -

        I am marking this issue as resolved.

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - I am marking this issue as resolved.

          People

          • Assignee:
            noreply.ceki@qos.ch Ceki Gulcu
            Reporter:
            cbeams Chris Beams
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: