Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-2717

Slow initialization under Windows

VotersWatch issueWatchersLinkCloneUpdate Comment AuthorReplace String in CommentUpdate Comment VisibilityDelete Comments
    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Fixed
    • 2.12.0, 2.12.1
    • 2.13.1
    • Core
    • None
    • Tested JDKs:

      • jdk1.8.0_221
      • jdk-9.0.4
      • jdk-11.0.4
      • jdk-12.0.2
      • jdk-13.0.1

      Tested OS: Windows 10 1809

    Description

      Together with feature LOG4J2-913 (included in 2.12.0) was introduced in commit cb905f37c1ec10e8aa7637dd9770e3cf4672c830 (https://gitbox.apache.org/repos/asf?p=logging-log4j2.git;h=cb905f3) following change in the file WatchManager.java (https://gitbox.apache.org/repos/asf?p=logging-log4j2.git;a=blob;f=log4j-core/src/main/java/org/apache/logging/log4j/core/util/WatchManager.java;h=3e3715258b498a55247e52d1cc360a91f5681a8f;hb=cb905f3)

      private final UUID id = UuidUtil.getTimeBasedUuid();
      

      This change is causing that during log4j2 initialization are enumerated network interfaces (seems to be quite slow operation under Windows).

      Behavior can be reproduced with the simple test program:

      package test;
      
      import org.apache.logging.log4j.LogManager;
      import org.apache.logging.log4j.Logger;
      
      public class TestLog4j2Startup {
          public static void main(String[] args) {
              System.out.println("Test started");
      
              System.out.println("Starting to initialize the logger");
              long startTime = System.currentTimeMillis();
              Logger logger = LogManager.getLogger();
              long endTime = System.currentTimeMillis();
              System.out.println("Logger initialization took " + (endTime - startTime) + " ms");
      
              logger.info("Hello from log4j2!");
      
              System.out.println("Test finished");
          }
      }
      

      Execution of the following command then prints how much time initialization takes:

      java -cp .;log4j-api-2.12.1.jar;log4j-core-2.12.1.jar test.TestLog4j2Startup

      Delay is depending on number of enabled network interfaces. In our case delay in the initialization is between 5 to 10 seconds.

      The same command with log4j2 version 2.11.2 is executed as expected (within few hundreds of milliseconds).

      Suggested solution: Late initialization of the id field or different mechanism how id is generated.

      Attachments

        Activity

          This comment will be Viewable by All Users Viewable by All Users
          Cancel

          People

            rgoers Ralph Goers
            libor.svehlak Libor Svehlak
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Slack

                Issue deployment