-
Bug
-
Resolution: Done
-
Major
-
7.4.16.GA
-
None
-
False
-
False
-
-
-
-
-
-
-
-
Undefined
-
Workaround Exists
-
-
When defining log4j filters in log4j.xml or properties in webapp, getLogger() occurred at org.apache.log4j.JBossFilterWrapper.isLoggable() [1].
Running with JDK11, the logger lookup is much slower than JDK 8 and high cpu loaded even though the version was fixed for JBEAP-19267.
This slowness can be seen both 7.3.5 and 7.2.9.
[1]
"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)
For example, the reproducer attached calls Log.debug() 100,000 times in 1 request. Then the execution time of JDK11 is about 3 times slower on my test.
- JDK8
INFO stdout - Instantiating 100000 loggers: duration = 8340024975 nanos = 8340 millis = 8 seconds - JDK11
INFO stdout - Instantiating 100000 loggers: duration = 24177532183 nanos = 24177 millis = 24 seconds
- is incorporated by
-
JBEAP-20923 [GSS](7.3.z) Logger is slower with log4j filter on JDK11
- Closed
-
JBEAP-27101 (7.4.z) Upgrade log4j-jboss-logmanager from 1.2.2.Final-redhat-00002 to 1.3.1.Final-redhat-00002
- Closed