Using logging API causes high cpu and slower on JDK11 when application has log4j filter settings

Solution Verified - Updated 19 Aug 2024

Environment

Red Hat JBoss Enterprise Application Platform (EAP)
- 7.2.x
- 7.3.x
- 7.4.x
OpenJDK 11

Issue

When web application on JDK 11 has log4j configuration file to use filiter, using logging API can cause high cpu and slower.
The thread dump can see the following stacktrace as the high cpu thread.

"default task-1" #165 prio=5 os_prio=0 cpu=2405.82ms elapsed=2.66s tid=0x0000559632236800 nid=0x2f2e runnable  [0x00007fa84327a000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames(java.base@11.0.7/Native Method)
	at java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames(java.base@11.0.7/StackStreamFactory.java:386)
	at java.lang.StackStreamFactory$AbstractStackWalker.getNextBatch(java.base@11.0.7/StackStreamFactory.java:322)
	at java.lang.StackStreamFactory$AbstractStackWalker.peekFrame(java.base@11.0.7/StackStreamFactory.java:263)
	at java.lang.StackStreamFactory$AbstractStackWalker.hasNext(java.base@11.0.7/StackStreamFactory.java:351)
	at java.lang.StackStreamFactory$StackFrameTraverser.tryAdvance(java.base@11.0.7/StackStreamFactory.java:593)
	at java.util.Spliterators$1Adapter.hasNext(java.base@11.0.7/Spliterators.java:681)
	at org.jboss.logmanager.JDKSpecific$FindAllWalkFunction.apply(JDKSpecific.java:210)
	at org.jboss.logmanager.JDKSpecific$FindAllWalkFunction.apply(JDKSpecific.java:198)
	at java.lang.StackStreamFactory$StackFrameTraverser.consumeFrames(java.base@11.0.7/StackStreamFactory.java:534)
	at java.lang.StackStreamFactory$AbstractStackWalker.doStackWalk(java.base@11.0.7/StackStreamFactory.java:306)
	at java.lang.StackStreamFactory$AbstractStackWalker.callStackWalk(java.base@11.0.7/Native Method)
	at java.lang.StackStreamFactory$AbstractStackWalker.beginStackWalk(java.base@11.0.7/StackStreamFactory.java:370)
	at java.lang.StackStreamFactory$AbstractStackWalker.walk(java.base@11.0.7/StackStreamFactory.java:243)
	at java.lang.StackWalker.walk(java.base@11.0.7/StackWalker.java:498)
	at org.jboss.logmanager.JDKSpecific.logContextFinder(JDKSpecific.java:70)
	at org.jboss.logmanager.ClassLoaderLogContextSelector$2.run(ClassLoaderLogContextSelector.java:109)
	at org.jboss.logmanager.ClassLoaderLogContextSelector$2.run(ClassLoaderLogContextSelector.java:107)
	at org.jboss.logmanager.ClassLoaderLogContextSelector.getLogContext(ClassLoaderLogContextSelector.java:122)
	at org.jboss.as.logging.logmanager.WildFlyLogContextSelectorImpl.getLogContext(WildFlyLogContextSelectorImpl.java:75)
	at org.jboss.logmanager.LogContext.getLogContext(LogContext.java:301)
	at org.apache.log4j.JBossLogManagerFacade$1.run(JBossLogManagerFacade.java:37)
	at org.apache.log4j.JBossLogManagerFacade$1.run(JBossLogManagerFacade.java:34)
	at org.apache.log4j.JBossLogManagerFacade.doPrivileged(JBossLogManagerFacade.java:269)
	at org.apache.log4j.JBossLogManagerFacade.getLogContext(JBossLogManagerFacade.java:246)
	at org.apache.log4j.JBossLogManagerFacade.getJBossLogger(JBossLogManagerFacade.java:52)
	at org.apache.log4j.JBossLogManagerFacade.getOrCreateLogger(JBossLogManagerFacade.java:148)
	at org.apache.log4j.Hierarchy.getLogger(Hierarchy.java:130)
	at org.apache.log4j.Hierarchy.getLogger(Hierarchy.java:125)
	at org.apache.log4j.LogManager.getLogger(LogManager.java:57)
	at org.apache.log4j.Logger.getLogger(Logger.java:35)
	at org.apache.log4j.JBossFilterWrapper.isLoggable(JBossFilterWrapper.java:27)
	at org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:33)
	at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:77)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:333)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:341)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:341)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:341)
	at org.jboss.logmanager.Logger.logRaw(Logger.java:852)
	at org.apache.log4j.Category.callAppenders(Category.java:69)
	at org.apache.log4j.Category.forcedLog(Category.java:121)
	at org.apache.log4j.Category.debug(Category.java:82)
	at com.example.TestServlet.doGet(TestServlet.java:23)

Update EAP to 7.2.9 according to the Logger Lookup Much Slower and High CPU on JDK11, but the issue still occurred.

Resolution

Update to EAP 7.4.18+
Or apply either one of the following workarounds.
Remove filter definition from log4j.xml/properties.
The log4j filters would be defined like following example.

   <appender name="stdout" class="org.apache.log4j.ConsoleAppender">
      ...
      <!-- remove or comment out the filter definition -->
      <filter class="org.apache.log4j.varia.StringMatchFilter">
         <param name="StringToMatch" value="test" />
         <param name="AcceptOnMatch" value="false" />
      </filter>
      ...
   </appender>

Packaging the log4j library per-deployment
Include log4j jar file to WEB-INF/lib (if using commons-logging, that needs to be included also.) and add exclusion setting as WEB-INF/jboss-deployment-structure.xml as follows. Then set use-deployment-logging-config to false in logging subsystem.
This step is mentioned as same as Manually configured per-deployment configuration in How do I configure Log4J in EAP 6/7?.

<jboss-deployment-structure>
    <deployment>
      <exclusions>
        <module name="org.apache.log4j"/>
        <module name="org.apache.commons.logging"/>
      </exclusions>
    </deployment>
</jboss-deployment-structure>

/subsystem=logging:write-attribute(name=use-deployment-logging-config,value=false)

Root Cause

This content is not included.JBEAP-27100

SBR

JBoss Base AS

Product(s)

Red Hat JBoss Enterprise Application Platform

Components

jbossas

Category

Troubleshoot

Tags

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.