[
https://issues.apache.org/jira/browse/LOG4J2-2940?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Peter H updated LOG4J2-2940:
----------------------------
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?
{noformat}at
java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames([email protected]/Native
Method)
at
java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames([email protected]/StackStreamFactory.java:386)
at
java.lang.StackStreamFactory$AbstractStackWalker.getNextBatch([email protected]/StackStreamFactory.java:322)
at
java.lang.StackStreamFactory$AbstractStackWalker.peekFrame([email protected]/StackStreamFactory.java:263)
at
java.lang.StackStreamFactory$AbstractStackWalker.hasNext([email protected]/StackStreamFactory.java:351)
at
java.lang.StackStreamFactory$StackFrameTraverser.tryAdvance([email protected]/StackStreamFactory.java:593)
at
java.util.stream.ReferencePipeline.forEachWithCancel([email protected]/ReferencePipeline.java:127)
at
java.util.stream.AbstractPipeline.copyIntoWithCancel([email protected]/AbstractPipeline.java:502)
at
java.util.stream.AbstractPipeline.copyInto([email protected]/AbstractPipeline.java:488)
at
java.util.stream.AbstractPipeline.wrapAndCopyInto([email protected]/AbstractPipeline.java:474)
at
java.util.stream.FindOps$FindOp.evaluateSequential([email protected]/FindOps.java:150)
at
java.util.stream.AbstractPipeline.evaluate([email protected]/AbstractPipeline.java:234)
at
java.util.stream.ReferencePipeline.findFirst([email protected]/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([email protected]/StackStreamFactory.java:534)
at
java.lang.StackStreamFactory$AbstractStackWalker.doStackWalk([email protected]/StackStreamFactory.java:306)
at
java.lang.StackStreamFactory$AbstractStackWalker.callStackWalk([email protected]/Native
Method)
at
java.lang.StackStreamFactory$AbstractStackWalker.beginStackWalk([email protected]/StackStreamFactory.java:370)
at
java.lang.StackStreamFactory$AbstractStackWalker.walk([email protected]/StackStreamFactory.java:243)
at java.lang.StackWalker.walk([email protected]/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)
...{noformat}
was:
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 entire 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 I believe that to get to the required class it isn't actually necessary
to do it this rather expensive way, but rather use an approach similar to what
jboss-logging library developers used when working on the following issue:
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
{noformat}at
java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames([email protected]/Native
Method)
at
java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames([email protected]/StackStreamFactory.java:386)
at
java.lang.StackStreamFactory$AbstractStackWalker.getNextBatch([email protected]/StackStreamFactory.java:322)
at
java.lang.StackStreamFactory$AbstractStackWalker.peekFrame([email protected]/StackStreamFactory.java:263)
at
java.lang.StackStreamFactory$AbstractStackWalker.hasNext([email protected]/StackStreamFactory.java:351)
at
java.lang.StackStreamFactory$StackFrameTraverser.tryAdvance([email protected]/StackStreamFactory.java:593)
at
java.util.stream.ReferencePipeline.forEachWithCancel([email protected]/ReferencePipeline.java:127)
at
java.util.stream.AbstractPipeline.copyIntoWithCancel([email protected]/AbstractPipeline.java:502)
at
java.util.stream.AbstractPipeline.copyInto([email protected]/AbstractPipeline.java:488)
at
java.util.stream.AbstractPipeline.wrapAndCopyInto([email protected]/AbstractPipeline.java:474)
at
java.util.stream.FindOps$FindOp.evaluateSequential([email protected]/FindOps.java:150)
at
java.util.stream.AbstractPipeline.evaluate([email protected]/AbstractPipeline.java:234)
at
java.util.stream.ReferencePipeline.findFirst([email protected]/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([email protected]/StackStreamFactory.java:534)
at
java.lang.StackStreamFactory$AbstractStackWalker.doStackWalk([email protected]/StackStreamFactory.java:306)
at
java.lang.StackStreamFactory$AbstractStackWalker.callStackWalk([email protected]/Native
Method)
at
java.lang.StackStreamFactory$AbstractStackWalker.beginStackWalk([email protected]/StackStreamFactory.java:370)
at
java.lang.StackStreamFactory$AbstractStackWalker.walk([email protected]/StackStreamFactory.java:243)
at java.lang.StackWalker.walk([email protected]/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)
...{noformat}
> High CPU at Java 11 due to the use of StackWalker from
> StackLocator.getCallerClass
> ----------------------------------------------------------------------------------
>
> Key: LOG4J2-2940
> URL: https://issues.apache.org/jira/browse/LOG4J2-2940
> Project: Log4j 2
> Issue Type: Bug
> Components: API
> Affects Versions: 2.13.3
> Reporter: Peter H
> Priority: Major
>
> 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?
> {noformat}at
> java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames([email protected]/Native
> Method)
> at
> java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames([email protected]/StackStreamFactory.java:386)
> at
> java.lang.StackStreamFactory$AbstractStackWalker.getNextBatch([email protected]/StackStreamFactory.java:322)
> at
> java.lang.StackStreamFactory$AbstractStackWalker.peekFrame([email protected]/StackStreamFactory.java:263)
> at
> java.lang.StackStreamFactory$AbstractStackWalker.hasNext([email protected]/StackStreamFactory.java:351)
> at
> java.lang.StackStreamFactory$StackFrameTraverser.tryAdvance([email protected]/StackStreamFactory.java:593)
> at
> java.util.stream.ReferencePipeline.forEachWithCancel([email protected]/ReferencePipeline.java:127)
> at
> java.util.stream.AbstractPipeline.copyIntoWithCancel([email protected]/AbstractPipeline.java:502)
> at
> java.util.stream.AbstractPipeline.copyInto([email protected]/AbstractPipeline.java:488)
> at
> java.util.stream.AbstractPipeline.wrapAndCopyInto([email protected]/AbstractPipeline.java:474)
> at
> java.util.stream.FindOps$FindOp.evaluateSequential([email protected]/FindOps.java:150)
> at
> java.util.stream.AbstractPipeline.evaluate([email protected]/AbstractPipeline.java:234)
> at
> java.util.stream.ReferencePipeline.findFirst([email protected]/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([email protected]/StackStreamFactory.java:534)
> at
> java.lang.StackStreamFactory$AbstractStackWalker.doStackWalk([email protected]/StackStreamFactory.java:306)
> at
> java.lang.StackStreamFactory$AbstractStackWalker.callStackWalk([email protected]/Native
> Method)
> at
> java.lang.StackStreamFactory$AbstractStackWalker.beginStackWalk([email protected]/StackStreamFactory.java:370)
> at
> java.lang.StackStreamFactory$AbstractStackWalker.walk([email protected]/StackStreamFactory.java:243)
> at java.lang.StackWalker.walk([email protected]/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)
> ...{noformat}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
