[LOG4J2-2940] High CPU at Java 11 due to the use of StackWalker from StackLocator.getCallerClass

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.13.3
• Component/s: API
• External issue URL: https://bugzilla.redhat.com/show_bug.cgi?id=1813436
• Assignee: Ralph Goers
• Reporter: Peter H
• Created: 08/Oct/20 20:21
• Updated: 04/Aug/21 13:46
• Resolved: 03/Apr/21 15:16

Description

We're encountering an issue similar to LOG4J2-2792 and LOG4J2-2880 but it isn't because of the use of Location, but because of the use of dynamically created loggers that we then refer to via org.slf4j.LoggerFactory.getLogger(method.getDeclaringClass()). This attempts to get the caller class and ends up walking the stack as in the stack trace example below. This is known to be rather problematic (from the performance perspective) and even becomes worse with the time (until the JVM restart, or full GC) - https://bugs.openjdk.java.net/browse/JDK-8222942 for example.

However instead of doing it this rather expensive way, it may be possible to use an improved approach similar to what jboss-logging library developers used when working on the following issues:
https://bugzilla.redhat.com/show_bug.cgi?id=1813436
https://issues.redhat.com/browse/LOGMGR-263
The related commit: https://github.com/jboss-logging/jboss-logmanager/commit/fc1fc3b509df9797ff06a423878a5b113f6281f8
Can you check whether something useful may be brought in from that?

at java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames(java.base@11.0.8/Native Method)
at java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames(java.base@11.0.8/StackStreamFactory.java:386)
at java.lang.StackStreamFactory$AbstractStackWalker.getNextBatch(java.base@11.0.8/StackStreamFactory.java:322)
at java.lang.StackStreamFactory$AbstractStackWalker.peekFrame(java.base@11.0.8/StackStreamFactory.java:263)
at java.lang.StackStreamFactory$AbstractStackWalker.hasNext(java.base@11.0.8/StackStreamFactory.java:351)
at java.lang.StackStreamFactory$StackFrameTraverser.tryAdvance(java.base@11.0.8/StackStreamFactory.java:593)
at java.util.stream.ReferencePipeline.forEachWithCancel(java.base@11.0.8/ReferencePipeline.java:127)
at java.util.stream.AbstractPipeline.copyIntoWithCancel(java.base@11.0.8/AbstractPipeline.java:502)
at java.util.stream.AbstractPipeline.copyInto(java.base@11.0.8/AbstractPipeline.java:488)
at java.util.stream.AbstractPipeline.wrapAndCopyInto(java.base@11.0.8/AbstractPipeline.java:474)
at java.util.stream.FindOps$FindOp.evaluateSequential(java.base@11.0.8/FindOps.java:150)
at java.util.stream.AbstractPipeline.evaluate(java.base@11.0.8/AbstractPipeline.java:234)
at java.util.stream.ReferencePipeline.findFirst(java.base@11.0.8/ReferencePipeline.java:543)
at org.apache.logging.log4j.util.StackLocator.lambda$getCallerClass$6(StackLocator.java:58)
at org.apache.logging.log4j.util.StackLocator$$Lambda$1226/0x00000008414fec40.apply(Unknown Source)
at java.lang.StackStreamFactory$StackFrameTraverser.consumeFrames(java.base@11.0.8/StackStreamFactory.java:534)
at java.lang.StackStreamFactory$AbstractStackWalker.doStackWalk(java.base@11.0.8/StackStreamFactory.java:306)
at java.lang.StackStreamFactory$AbstractStackWalker.callStackWalk(java.base@11.0.8/Native Method)
at java.lang.StackStreamFactory$AbstractStackWalker.beginStackWalk(java.base@11.0.8/StackStreamFactory.java:370)
at java.lang.StackStreamFactory$AbstractStackWalker.walk(java.base@11.0.8/StackStreamFactory.java:243)
at java.lang.StackWalker.walk(java.base@11.0.8/StackWalker.java:498)
at org.apache.logging.log4j.util.StackLocator.getCallerClass(StackLocator.java:57)
at org.apache.logging.log4j.util.StackLocatorUtil.getCallerClass(StackLocatorUtil.java:67)
at org.apache.logging.slf4j.Log4jLoggerFactory.getContext(Log4jLoggerFactory.java:45)
at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:48)
at org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:30)
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:363)
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:388)
at LoggerAspect.isLogLevelEnabled(LoggerAspect.java:91)
...

Issue Links

• is blocked by: LOG4J2-2975 SLF4J fluent API fails to capture call site location due to missing LoggingEventAware implementation
• links to: GitHub Pull Request #475
• links to: GitHub Pull Request #479
• links to: GitHub Pull Request #505