[GEODE-8875] Geode is spending a lot of time in log4j classpath scanning on startup

• Type: Improvement
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 1.14.0
• Component/s: logging
• Labels: pull-request-available
• Assignee: Dan Smith
• Reporter: Dan Smith
• Created: 26/Jan/21 23:14
• Updated: 03/Sep/21 02:23
• Resolved: 02/Feb/21 00:07

Description

When running gfsh, it takes a long time even to run the `gfsh help` command. For example, with our docker image it takes 10 seconds just to display the help from

docker run apachegeode/geode:latest time gfsh help

Doing some CPU sampling, it looks like the majority of the time is in log4j2 scanning for plugins.

TRACE 300879: (thread=200001)
        java.lang.ClassLoader.defineClass1(ClassLoader.java:Unknown line)
        java.lang.ClassLoader.defineClass(ClassLoader.java:763)
        java.security.SecureClassLoader.defineClass(SecureClassLoader.java:142)
        java.net.URLClassLoader.defineClass(URLClassLoader.java:468)
        java.net.URLClassLoader.access$100(URLClassLoader.java:74)
        java.net.URLClassLoader$1.run(URLClassLoader.java:369)
        java.net.URLClassLoader$1.run(URLClassLoader.java:363)
        java.security.AccessController.doPrivileged(AccessController.java:Unknown line)
        java.net.URLClassLoader.findClass(URLClassLoader.java:362)
        java.lang.ClassLoader.loadClass(ClassLoader.java:424)
        sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:349)
        java.lang.ClassLoader.loadClass(ClassLoader.java:357)
        org.apache.logging.log4j.core.config.plugins.util.ResolverUtil.addIfMatching(ResolverUtil.java:449)
        org.apache.logging.log4j.core.config.plugins.util.ResolverUtil.loadImplementationsInJar(ResolverUtil.java:351)
        org.apache.logging.log4j.core.config.plugins.util.ResolverUtil.findInPackage(ResolverUtil.java:233)
        org.apache.logging.log4j.core.config.plugins.util.PluginRegistry.loadFromPackage(PluginRegistry.java:221)
        org.apache.logging.log4j.core.config.plugins.util.PluginManager.collectPlugins(PluginManager.java:152)
        org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:224)
        org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:288)
      org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:579)

After further investigation, this scanning appears to be caused by this line in our log4j2-cli.xml file, which sets the packages to be "org.apache.geode" This causes log4j2 to scan all of our jar files.

<Configuration status="WARN" shutdownHook="disable" packages="org.apache.geode">

This scanning is completely unnecessary because log4j already has an annotation processor which generates a file that log4j2 can find without any scanning.

This probably affects geode server startup, not just gfsh, because log4j2.xml has this setting as well.

Issue Links

• links to: GitHub Pull Request #5957