Using logging API causes high cpu and slower on JDK11 when application has log4j filter settings
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.
Environment
- Red Hat JBoss Enterprise Application Platform (EAP)
- 7.2.x
- 7.3.x
- 7.4.x
- OpenJDK 11
Subscriber exclusive content
A Red Hat subscription provides unlimited access to our knowledgebase, tools, and much more.