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

Slow initialization under Windows

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 2.12.0, 2.12.1
    • Fix Version/s: 2.13.1
    • Component/s: Core
    • Labels:
      None
    • Environment:

      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

            People

            • Assignee:
              rgoers Ralph Goers
              Reporter:
              libor.svehlak Libor Svehlak
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: