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

Class loading for extended stack traces causes performance issues

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 2.11.2
    • Fix Version/s: None
    • Component/s: Core
    • Labels:
      None

      Description

      Extended stack traces invoke class loading, including for classes such as "jdk/internal/reflect/GeneratedMethodAccessor183.class".

       

      When running  e.g. springboot+Tomcat with a fat-jar, this class loading is delegated to TomcatEmbeddedWebappClassLoader, which will unzip JAR files in an attempt to find the class.  This causes performance issues, as JAR files are unzipped every time an exception with one of these classes in the stack is logged.

      In the case of TomcatEmbeddedWebappClassLoader, there is a caching mechanism in place but this particular code path bypasses the cache, due to the filename pattern being searched for (starts-with "/WEB-INF/classes", ends-with ".class").

      Others have also noticed performance issues here, due to locking in Jetty's classloader: https://stackoverflow.com/questions/53627883/how-to-stop-log4j2-load-class-in-exception-stack

       

      Example stack trace:

         java.lang.Thread.State: RUNNABLE
      	at java.util.zip.Inflater.inflateBytesBytes(java.base@11.0.3/Native Method)
      	at java.util.zip.Inflater.inflate(java.base@11.0.3/Inflater.java:385)
      	- locked <0x00000000c337ca78> (a java.util.zip.Inflater$InflaterZStreamRef)
      	at java.util.zip.InflaterInputStream.read(java.base@11.0.3/InflaterInputStream.java:153)
      	at java.util.zip.ZipInputStream.read(java.base@11.0.3/ZipInputStream.java:195)
      	at java.util.jar.JarInputStream.read(java.base@11.0.3/JarInputStream.java:207)
      	at java.util.zip.ZipInputStream.closeEntry(java.base@11.0.3/ZipInputStream.java:141)
      	at java.util.zip.ZipInputStream.getNextEntry(java.base@11.0.3/ZipInputStream.java:119)
      	at java.util.jar.JarInputStream.getNextEntry(java.base@11.0.3/JarInputStream.java:142)
      	at java.util.jar.JarInputStream.getNextJarEntry(java.base@11.0.3/JarInputStream.java:179)
      	at org.apache.catalina.webresources.JarWarResourceSet.getArchiveEntries(JarWarResourceSet.java:117)
      	- locked <0x00000000d6fc7d00> (a java.lang.Object)
      	at org.apache.catalina.webresources.AbstractArchiveResourceSet.getResource(AbstractArchiveResourceSet.java:253)
      	at org.apache.catalina.webresources.StandardRoot.getResourceInternal(StandardRoot.java:282)
      	at org.apache.catalina.webresources.Cache.getResource(Cache.java:62)
      	at org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:217)
      	at org.apache.catalina.webresources.StandardRoot.getClassLoaderResource(StandardRoot.java:226)
      	at org.apache.catalina.loader.WebappClassLoaderBase.findClassInternal(WebappClassLoaderBase.java:2303)
      	at org.apache.catalina.loader.WebappClassLoaderBase.findClass(WebappClassLoaderBase.java:865)
      	at org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader.findClassIgnoringNotFound(TomcatEmbeddedWebappClassLoader.java:119)
      	at org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader.doLoadClass(TomcatEmbeddedWebappClassLoader.java:84)
      	at org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader.loadClass(TomcatEmbeddedWebappClassLoader.java:66)
      	- locked <0x00000000d9741ce8> (a java.lang.Object)
      	at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1188)
      	at org.apache.logging.log4j.util.LoaderUtil.loadClass(LoaderUtil.java:166)
      	at org.apache.logging.log4j.core.impl.ThrowableProxyHelper.loadClass(ThrowableProxyHelper.java:218)
      	at org.apache.logging.log4j.core.impl.ThrowableProxyHelper.toExtendedStackTrace(ThrowableProxyHelper.java:114)
      	at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:109)
      	at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:93)
      	at org.apache.logging.log4j.core.impl.Log4jLogEvent.getThrownProxy(Log4jLogEvent.java:605)
      	at org.apache.logging.log4j.core.impl.Log4jLogEvent.serialize(Log4jLogEvent.java:718)
      	at org.apache.logging.log4j.core.impl.Log4jLogEvent.createMemento(Log4jLogEvent.java:772)
      	at org.apache.logging.log4j.core.appender.AsyncAppender.append(AsyncAppender.java:162)
      	at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
      	at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
      	at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
      	at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
      	at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:464)
      	at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:448)
      	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:431)
      	at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:455)
      	at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:450)
      	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:431)
      	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
      	at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
      	at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
      	at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2170)
      	at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2125)
      	at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2108)
      	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2002)
      	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1974)
      	at org.apache.logging.slf4j.Log4jLogger.error(Log4jLogger.java:319)

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              joedj Joe Jordan
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated: