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

ContextDataProvider will cause concurrent threads blocking at the first logging time

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Major
    • Resolution: Fixed
    • 2.13.2, 2.13.3
    • 2.14.0
    • Core
    • Java Version: 1.8.0_45

      Web Server: Tomcat 8.0.30

      OS: CentOS 6.8

    Description

      The recently introduced  `ContextDataProvider` use `ServiceLoader` to find all possible implementations of ContextDataProvider, which will try to scan all jar files. So when many new threads comes in the first logging time concurrently, all thread will be blocking on the` getProviders` method. It will make web service get very bad performance to serve requests in the beginning.

      Here is an example of blocking thread stack:

      at java.util.zip.ZipFile.getEntry (ZipFile.java:309)at java.util.zip.ZipFile.getEntry (ZipFile.java:309)at java.util.jar.JarFile.getEntry (JarFile.java:240)at java.util.jar.JarFile.getJarEntry (JarFile.java:223)at sun.misc.URLClassPath$JarLoader.getResource (URLClassPath.java:1005)at sun.misc.URLClassPath$JarLoader.findResource (URLClassPath.java:983)at sun.misc.URLClassPath$1.next (URLClassPath.java:240)at sun.misc.URLClassPath$1.hasMoreElements (URLClassPath.java:250)at java.net.URLClassLoader$3$1.run (URLClassLoader.java:601)at java.net.URLClassLoader$3$1.run (URLClassLoader.java:599)at java.security.AccessController.doPrivileged (Native Method)at java.net.URLClassLoader$3.next (URLClassLoader.java:598)at java.net.URLClassLoader$3.hasMoreElements (URLClassLoader.java:623)at sun.misc.CompoundEnumeration.next (CompoundEnumeration.java:45)at sun.misc.CompoundEnumeration.hasMoreElements (CompoundEnumeration.java:54)at sun.misc.CompoundEnumeration.next (CompoundEnumeration.java:45)at sun.misc.CompoundEnumeration.hasMoreElements (CompoundEnumeration.java:54)at java.util.ServiceLoader$LazyIterator.hasNextService (ServiceLoader.java:354)at java.util.ServiceLoader$LazyIterator.hasNext (ServiceLoader.java:393)at java.util.ServiceLoader$1.hasNext (ServiceLoader.java:474)at org.apache.logging.log4j.core.impl.ThreadContextDataInjector.getProviders (ThreadContextDataInjector.java:254)at org.apache.logging.log4j.core.impl.ThreadContextDataInjector.access$000 (ThreadContextDataInjector.java:53)at org.apache.logging.log4j.core.impl.ThreadContextDataInjector$ForDefaultThreadContextMap.<init> (ThreadContextDataInjector.java:74)at org.apache.logging.log4j.core.impl.ContextDataInjectorFactory.createDefaultInjector (ContextDataInjectorFactory.java:91)at org.apache.logging.log4j.core.impl.ContextDataInjectorFactory.createInjector (ContextDataInjectorFactory.java:71)at org.apache.logging.log4j.core.async.RingBufferLogEventTranslator.<init> (RingBufferLogEventTranslator.java:40)at org.apache.logging.log4j.core.async.AsyncLogger.getCachedTranslator (AsyncLogger.java:121)at org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator (AsyncLogger.java:222)at org.apache.logging.log4j.core.async.AsyncLogger.access$000 (AsyncLogger.java:67)at org.apache.logging.log4j.core.async.AsyncLogger$1.log (AsyncLogger.java:152)at org.apache.logging.log4j.core.async.AsyncLogger.log (AsyncLogger.java:136)at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage (AbstractLogger.java:2198)at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion (AbstractLogger.java:2152)at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely (AbstractLogger.java:2135)at org.apache.logging.log4j.spi.AbstractLogger.logMessage (AbstractLogger.java:2011)at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled (AbstractLogger.java:1983)at org.apache.logging.slf4j.Log4jLogger.warn

      Attachments

        Activity

          People

            Unassigned Unassigned
            emengjzs Zishun Jiao
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Time Tracking

                Estimated:
                Original Estimate - 48h
                48h
                Remaining:
                Time Spent - 0.5h Remaining Estimate - 47.5h
                47.5h
                Logged:
                Time Spent - 0.5h Remaining Estimate - 47.5h
                0.5h