You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "ASF subversion and git services (Jira)" <ji...@apache.org> on 2021/06/04 16:58:00 UTC

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

    [ https://issues.apache.org/jira/browse/LOG4J2-2940?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17357485#comment-17357485 ] 

ASF subversion and git services commented on LOG4J2-2940:
---------------------------------------------------------

Commit 97c89b9fa25042dec8d5d63ddcfb266c22d12d17 in logging-log4j2's branch refs/heads/master from Carter Kozak
[ https://gitbox.apache.org/repos/asf?p=logging-log4j2.git;h=97c89b9 ]

Fix incorrect LogManager accessor used by LOG4J2-2940

The `getContext()` accessor with no args has been used as a fallback
for Log4jLoggerFactory slf4j implementations for a while, but it's
much more likely to be used now that LOG4J2-2940 is resolved.
Without the `false` argument, the first slf4j LoggerFactory.getLogger
call will not cause log4j to initialize itself.


> 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
>            Assignee: Ralph Goers
>            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(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)
> ...{noformat}



--
This message was sent by Atlassian Jira
(v8.3.4#803005)