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

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.13.2, 2.13.3
• Fix Version/s: 2.14.0
• Component/s: Core
• Labels: performance

Environment

Java Version: 1.8.0_45

Web Server: Tomcat 8.0.30

OS: CentOS 6.8

• Assignee: Unassigned
• Reporter: Zishun Jiao
• Created: 11/Jun/20 11:42
• Updated: 16/Jul/20 20:43
• Resolved: 29/Jun/20 00:48

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