Uploaded image for project: 'Minecraft: Java Edition'
  1. Minecraft: Java Edition
  2. MC-118594

Removal of Log4J2Plugins.dat causing a slowdown of 3 secs on startup while it has to rescan all classes

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Resolved
    • Resolution: Fixed
    • Affects Version/s: Minecraft 1.12, Minecraft 1.13, Minecraft 18w30b, Minecraft 1.13.1, Minecraft 1.13.2, Minecraft 19w12b, Minecraft 19w13b, Minecraft 19w14a, Minecraft 19w14b, Minecraft 1.14 Pre-Release 2
    • Fix Version/s: 20w22a
    • Labels:
    • Confirmation Status:
      Unconfirmed
    • Category:
      (Unassigned)

      Description

      This is a regression introduced by the fix for MC-115797. It delays the server start about 2 or more seconds and makes adding custom Log4J plugins much harder.

      Log4J is more or less modular: the core consists mostly out of independent plugins.

      There are two ways it can find them at runtime:

      • By scanning the classpath. This is not really optimized so it just loads all classes in a certain package and checks if they are annotated with the plugin annotation.
      • For performance they have an annotation processor that writes the available plugins into a Log4J2Plugins.dat file.

      In the old Log4J version before Minecraft 1.12 the annotation processor was not yet included, so only the log4j-core actually used the Log4J2Plugins.dat file. In newer log4j versions the metadata file is also generated for custom plugins now, theoretically removing the need for any classpath scanning. However, the server JAR caused issues (see MC-115797) because the shaded server JAR now included Log4J2Plugins.dat twice, once for log4j-core and once for authlib.

      The solution for that is to merge them, and there are tools available to do this for Maven and Gradle. However, it was fixed by excluding both, even the one from log4j-core! Log4J handles that gracefully, however the consequence is that is forced to classload literally every single of its classes to check if they are plugins, not only a few classes from custom plugins.

      You can easily see that if you enable Log4J's debug logging. It even shows several exceptions because it loads classes with missing dependencies (which are never used in Minecraft). See: debug.log

      You can get this debug log by running:

      java -Dorg.apache.logging.log4j.simplelog.StatusLogger.level=ALL -jar minecraft_server.1.12.jar
      

      Loading all the classes takes about 2 or 3 seconds when starting the Vanilla server and can be observed by the delay until the first message is printed. It doesn't cause actual issues until a mod adds another Log4J plugin to the classpath: As soon as one Log4J2Plugins.dat exist on the classpath, Log4J will no longer scan its classes, resulting in MC-115797 again.

      The proper fix for this is to merge the Log4J2Plugins.dat for log4j-core and authlib. There are tools available for Gradle and Maven to do this:

      Once this is done, classpath scanning can be disabled entirely by removing packages="com.mojang.util" from the log4j2.xml configuration. Log4J will detect them automatically.

      I've also attached two profiler screenshots that show the difference with, and without Log4J2Plugins.dat on the classpath. The server starts noticeably faster with it on the classpath.

        Attachments

        1. debug.log
          338 kB
        2. no-log4j2plugins-dat.png
          no-log4j2plugins-dat.png
          201 kB
        3. with-log4j2plugins-dat.png
          with-log4j2plugins-dat.png
          190 kB

          Activity

            People

            Assignee:
            Unassigned Unassigned
            Reporter:
            Minecrell Minecrell
            Votes:
            2 Vote for this issue
            Watchers:
            7 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: