Repetitive class static variable creation using getLogger becomes slower and slower

[puchengy]

Hi there, I have the below class that I have to repeatedly load by different classloaders.

public class HiveCatalog ... {
   ...
  private static final long logstartTime = System.nanoTime();
  private static final Logger LOG = LoggerFactory.getLogger(HiveCatalog.class);
  static {
    long logendtime = System.nanoTime();
    double milDuration = TimeUnit.NANOSECONDS.toMillis(logendtime - logstartTime);
    double duration = TimeUnit.NANOSECONDS.toSeconds(logendtime - logstartTime);
    LOG.error("pyang debug: getLogger just called spent {} seconds {} miliseconds", duration, milDuration);
  }
   ...
}

Each initialization of the class will trigger the static variable to be created. I noticed that the logger creation time becomes longer and longer, it used to finish for about 10 ms and then becomes more than 5s, and even more later.

Below is a thread dump in case it is helpful

"iceberg-rest-3367" #3367 daemon prio=5 os_prio=0 cpu=22033.65ms elapsed=2409.08s tid=0x000072d48c0a4800 nid=0x37ce waiting on condition  [0x000072d5255fb000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
	- parking to wait for  <0x000072dab6103e08> (a java.util.concurrent.locks.ReentrantReadWriteLock$FairSync)
	at java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt([email protected]/AbstractQueuedSynchronizer.java:885)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued([email protected]/AbstractQueuedSynchronizer.java:917)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire([email protected]/AbstractQueuedSynchronizer.java:1240)
	at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock([email protected]/ReentrantReadWriteLock.java:959)
	at com.sun.jmx.mbeanserver.Repository.remove([email protected]/Repository.java:619)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.unregisterFromRepository([email protected]/DefaultMBeanServerInterceptor.java:1896)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.exclusiveUnregisterMBean([email protected]/DefaultMBeanServerInterceptor.java:444)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.unregisterMBean([email protected]/DefaultMBeanServerInterceptor.java:411)
	at com.sun.jmx.mbeanserver.JmxMBeanServer.unregisterMBean([email protected]/JmxMBeanServer.java:546)
	at org.apache.logging.log4j.core.jmx.Server.unregisterAllMatching(Server.java:344)
	at org.apache.logging.log4j.core.jmx.Server.unregisterLoggerConfigs(Server.java:300)
	at org.apache.logging.log4j.core.jmx.Server.unregisterLoggerContext(Server.java:265)
	at org.apache.logging.log4j.core.jmx.Server.reregisterMBeansAfterReconfigure(Server.java:164)
	at org.apache.logging.log4j.core.jmx.Server.reregisterMBeansAfterReconfigure(Server.java:140)
	at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:642)
	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:713)
	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:735)
	at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:260)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:154)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:46)
	at org.apache.logging.log4j.LogManager.getContext(LogManager.java:197)
	at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:136)
	at org.apache.logging.slf4j.Log4jLoggerFactory.getContext(Log4jLoggerFactory.java:58)
	at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:46)
	at org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:32)
	at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:426)
	at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:451)
	at org.apache.iceberg.hive.HiveCatalog.<clinit>(HiveCatalog.java:75)
	at java.lang.Class.forName0([email protected]/Native Method)
	at java.lang.Class.forName([email protected]/Class.java:398)
	at org.apache.iceberg.common.DynConstructors$Builder.impl(DynConstructors.java:149)
	at org.apache.iceberg.CatalogUtil.loadCatalogUnisolated(CatalogUtil.java:267)
	at org.apache.iceberg.CatalogUtil.loadCatalog(CatalogUtil.java:247)
	at org.apache.iceberg.CatalogUtil.buildIcebergCatalog(CatalogUtil.java:355)

Appreciate if you have any thought on this, thanks!

[ppkarwasz]

@puchengy,

Which version of Log4j are you using? Did you try with the latest one (2.24.3)?

[puchengy]

Thank you for the suggestion. My issue seems resolved now using latest one (2.24.3), my previous version is 2.22.0.