[jira] [Created] (LOG4J2-2867) ContextDataProvider will cause concurrent threads blocking at the first logging time

["Zishun Jiao (Jira)" <ji...@apache.org>]

Zishun Jiao created LOG4J2-2867:
-----------------------------------

             Summary: ContextDataProvider will cause concurrent threads blocking at the first logging time
                 Key: LOG4J2-2867
                 URL: https://issues.apache.org/jira/browse/LOG4J2-2867
             Project: Log4j 2
          Issue Type: Bug
          Components: Core
    Affects Versions: 2.13.3, 2.13.2
         Environment: Java Version: 1.8.0_45

Web Server: Tomcat 8.0.30

OS: CentOS: 6.8
            Reporter: Zishun Jiao


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



--
This message was sent by Atlassian Jira
(v8.3.4#803005)