Bit of a long shot but here goes:
All this is running on an imx6 using kernel 5.10.63 and OpenJDK RTE 16.0.2+7.
I'm running a basic test app written in Java using slf4j 2.0.9 and log4j2 2.21.1. Calling LoggerFactoy.getLogger takes 20+ seconds to return after which logging is as expected.
My java app is:
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class Main
{
public static void main(String[] args)
{
Logger myLogger = LoggerFactory.getLogger("Test");
myLogger.info("This is a test log");
System.out.println("Hello world!");
}
}
and my log4j.xml
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="trace">
<Appenders>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout pattern="@timestamp:%d{yyyy-MM-dd/HH:mm:ss.SSS/zzz} message%m%n"/>;
</Console>
</Appenders>
<Loggers>
<Root level="trace">
<AppenderRef ref="Console"/>
</Root>
</Loggers>
</Configuration>
The application output (issuing date command on the same command line for reference):
Thu Jan 1 06:53:19 UTC 1970
DEBUG StatusLogger Using ShutdownCallbackRegistry class org.apache.logging.log4j.core.util.DefaultShutdownCallbackRegistry
TRACE StatusLogger Log4jLoggerFactory.getContext() found anchor class Main
DEBUG StatusLogger Took 1.562115 seconds to load 226 plugins from jdk.internal.loader.ClassLoaders$AppClassLoader@514713
DEBUG StatusLogger PluginManager 'Lookup' found 16 plugins
DEBUG StatusLogger AsyncLogger.ThreadNameStrategy=UNCACHED (user specified null, default is UNCACHED)
TRACE StatusLogger Using default SystemClock for timestamps.
DEBUG StatusLogger org.apache.logging.log4j.core.util.SystemClock supports precise timestamps.
DEBUG StatusLogger PluginManager 'Lookup' found 16 plugins
DEBUG StatusLogger PluginManager 'Converter' found 45 plugins
DEBUG StatusLogger Starting OutputStreamManager SYSTEM_OUT.false.false-1
DEBUG StatusLogger Starting LoggerContext[name=514713, org.apache.logging.log4j.core.LoggerContext@1a07e12]...
DEBUG StatusLogger Reconfiguration started for context[name=514713] at URI null (org.apache.logging.log4j.core.LoggerContext@1a07e12) with optional ClassLoader: null
DEBUG StatusLogger PluginManager 'Lookup' found 16 plugins
DEBUG StatusLogger PluginManager 'ConfigurationFactory' found 4 plugins
DEBUG StatusLogger PluginManager 'Lookup' found 16 plugins
DEBUG StatusLogger PluginManager 'Lookup' found 16 plugins
DEBUG StatusLogger Missing dependencies for Yaml support, ConfigurationFactory org.apache.logging.log4j.core.config.yaml.YamlConfigurationFactory is inactive
DEBUG StatusLogger PluginManager 'Lookup' found 16 plugins
DEBUG StatusLogger Missing dependencies for Json support, ConfigurationFactory org.apache.logging.log4j.core.config.json.JsonConfigurationFactory is inactive
DEBUG StatusLogger PluginManager 'Lookup' found 16 plugins
DEBUG StatusLogger Using configurationFactory org.apache.logging.log4j.core.config.ConfigurationFactory$Factory@1dc7102
DEBUG StatusLogger PluginManager 'Lookup' found 16 plugins
DEBUG StatusLogger Closing FileInputStream java.io.FileInputStream@333c60
DEBUG StatusLogger null null initializing configuration XmlConfiguration[location=/usr/share/ltest/log4j2.xml]
DEBUG StatusLogger PluginManager 'Core' found 131 plugins
DEBUG StatusLogger PluginManager 'Level' found 0 plugins
DEBUG StatusLogger PluginManager 'Lookup' found 16 plugins
DEBUG StatusLogger Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
TRACE StatusLogger TypeConverterRegistry initializing.
DEBUG StatusLogger PluginManager 'TypeConverter' found 26 plugins
DEBUG StatusLogger PatternLayout$Builder(pattern="@timestamp:%d{yyyy-MM-dd/HH:mm:ss.SSS/zzz} message%m%n", PatternSelector=null, Configuration(/usr/share/ltest/log4j2.xml), Replace=null, charset="null", alwaysWriteExceptions="null", disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null")
DEBUG StatusLogger PluginManager 'Converter' found 45 plugins
DEBUG StatusLogger Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.ConsoleAppender].
DEBUG StatusLogger ConsoleAppender$Builder(target="SYSTEM_OUT", follow="null", direct="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(@timestamp:%d{yyyy-MM-dd/HH:mm:ss.SSS/zzz} message%m%n), name="Console", Configuration(/usr/share/ltest/log4j2.xml), Filter=null, ={})
DEBUG StatusLogger Starting OutputStreamManager SYSTEM_OUT.false.false
DEBUG StatusLogger Building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin].
DEBUG StatusLogger createAppenders(={Console})
DEBUG StatusLogger Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
DEBUG StatusLogger createAppenderRef(ref="Console", level="null", Filter=null)
DEBUG StatusLogger Building Plugin[name=root, class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger].
DEBUG StatusLogger LoggerConfig$RootLogger$Builder(additivity="null", level="TRACE", levelAndRefs="null", includeLocation="null", ={Console}, ={}, Configuration(/usr/share/ltest/log4j2.xml), Filter=null)
DEBUG StatusLogger Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin].
DEBUG StatusLogger createLoggers(={root})
DEBUG StatusLogger Configuration XmlConfiguration[location=/usr/share/ltest/log4j2.xml] initialized
DEBUG StatusLogger Starting configuration XmlConfiguration[location=/usr/share/ltest/log4j2.xml]
DEBUG StatusLogger Started configuration XmlConfiguration[location=/usr/share/ltest/log4j2.xml] OK.
TRACE StatusLogger Stopping org.apache.logging.log4j.core.config.DefaultConfiguration@1cf94f8...
TRACE StatusLogger DefaultConfiguration notified 1 ReliabilityStrategies that config will be stopped.
TRACE StatusLogger DefaultConfiguration stopping root LoggerConfig.
TRACE StatusLogger DefaultConfiguration notifying ReliabilityStrategies that appenders will be stopped.
TRACE StatusLogger DefaultConfiguration stopping remaining Appenders.
DEBUG StatusLogger Shutting down OutputStreamManager SYSTEM_OUT.false.false-1
DEBUG StatusLogger OutputStream closed
DEBUG StatusLogger Shut down OutputStreamManager SYSTEM_OUT.false.false-1, all resources released: true
DEBUG StatusLogger Appender DefaultConsole-1 stopped with status true
TRACE StatusLogger DefaultConfiguration stopped 1 remaining Appenders.
TRACE StatusLogger DefaultConfiguration cleaning Appenders from 1 LoggerConfigs.
DEBUG StatusLogger Stopped org.apache.logging.log4j.core.config.DefaultConfiguration@1cf94f8 OK
TRACE StatusLogger Reregistering MBeans after reconfigure. Selector=org.apache.logging.log4j.core.selector.ClassLoaderContextSelector@1dbe163
TRACE StatusLogger Reregistering context (1/1): '514713' org.apache.logging.log4j.core.LoggerContext@1a07e12
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=514713'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=514713,component=StatusLogger'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=514713,component=ContextSelector'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=514713,component=Loggers,name=*'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=514713,component=Appenders,name=*'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=514713,component=AsyncAppenders,name=*'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=514713,component=AsyncLoggerRingBuffer'
TRACE StatusLogger Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=514713,component=Loggers,name=*,subtype=RingBuffer'
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=514713
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=514713,component=StatusLogger
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=514713,component=ContextSelector
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=514713,component=Loggers,name=
DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=514713,component=Appenders,name=Console
TRACE StatusLogger Using default SystemClock for timestamps.
DEBUG StatusLogger org.apache.logging.log4j.core.util.SystemClock supports precise timestamps.
TRACE StatusLogger Using DummyNanoClock for nanosecond timestamps.
DEBUG StatusLogger Reconfiguration complete for context[name=514713] at URI /usr/share/ltest/log4j2.xml (org.apache.logging.log4j.core.LoggerContext@1a07e12) with optional ClassLoader: null
DEBUG StatusLogger Shutdown hook enabled. Registering a new one.
DEBUG StatusLogger LoggerContext[name=514713, org.apache.logging.log4j.core.LoggerContext@1a07e12] started OK.
@timestamp:1970-01-01/06:53:43.679/UTC messageThis is a test log
Hello world!
I am very suspicious of multiple
DEBUG StatusLogger PluginManager 'Core' found 131 plugins
but no idea why these are present.
The class path shows: LoggerTest2.jar
The app start command line is: date;/usr/lib/jvm/java-16-openjdk/bin/java -Dlog4j2.debug=true -Dlog4j2.configurationFile=log4j2.xml -jar LoggerTest2.jar
The directory contents are:
LoggerTest2.jar
log4j-api-2.21.1.jar
log4j-core-2.21.1.jar
log4j-slf4j2-impl-2.21.1.jar
log4j2.xml
slf4j-api-2.0.9.jar
If I remove the log4j*.jar files the start up time is as expected and I get the default slf4j console output.
Running the same app on x86 (openjdk 16.0.1 2021-04-20) completes in <1s.