[
https://issues.apache.org/jira/browse/LOG4J2-2940?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17220507#comment-17220507
]
Ralph Goers edited comment on LOG4J2-2940 at 10/26/20, 6:33 AM:
----------------------------------------------------------------
Looking at the JBoss implementation I see that they are keeping track of the
LoggerContext in a Map with the ClassLoader as the key. Maybe JBoss can get
away with that but Log4j cannot. Instead, Log4j stores the LoggerContext in a
Map where the key is the identity hashcode of the ClassLoader. This should have
the same benefit with minimal extra overhead and won't run the risk of causing
ClassLoader leakage.
The comments for ClassLoaderContextSelector are "A log context selector which
chooses a log context based on the caller's classloader.", but that doesn't
seem to be what it does at all.
The algorithm JBoss seems to be using is:
# Call the JDK specific LogContextFinder passing in the Map of previously
located LogContexts and the LogContextFinder function (which just walks the
ClassLoader parent chain looking for the first LogContext it finds in the
ContextMap).
# Walks the StackFrames until it finds one whose class is associated with a
ClassLoader that can be found in the Map.
# If it doesn't find one it returns the default LogContext.
What really has me confused is I don't see any code that adds LogContext's to
the contextMap other than the registerLogContext method in
ClassLoaderContextSelector that IntelliJ says is never used. So it appears that
all this code ever does is return the default LogContext. Without some
algorithm to tell it to add a LogContext to the Map I don't see how the JBoss
code can be doing what it should be doing. I also don't see any tests in the
jboss-logging or jboss-logmanager projects to test this.
Am I misreading the code somehow?
I should contrast the algorithm that JBoss uses with the one Log4j uses:
# If the currentContext parameter is true then return the LoggerContext
associated with the ContextAnchor ThreadLocal. If one is not present the
default LoggerContext is returned.
# If the ClassLoader was specified locate the LoggerContext associated with
it, otherwise locate the caller's class (using StackLocatorUtil), get its
ClassLoader and locate the LoggerContext associated with it.
# To locate the LoggerContext check if the ClassLoader's identity is present
as a key in the contextMap. If it is return the LoggerContext. If not
recursively check its parents.
# Since no LoggerContext could be located, create a new one and register it
using the ClassLoader's identity as the key and return the created
LoggerContext.
After looking at the stack trace you provided I see that it isn't even in
Log4j's ClassLoaderContextSelector but the SLF4J adapter's getContext method.
It is trying to resolve the calling class to get its ClassLoader to pass to the
above algorithm. This probably shouldn't be handled this way because it you
have chosen to use a ContextSelector other than ClassLoaderContextSelect than
determining the caller's ClassLoader may be a waste of time. It should probably
just pass the FQCN.
I should also note that I have changed the algorithm the Java 9 version of
StackLocator is using. After doing further testing for LOG4J2-2880 I discovered
that the algorithm Log4j 2 originally used was better than what is in 2.13.3 so
that will be of some help in 2.14.0. That said, I suspect if I could directly
access the array of StackFrames using a for loop would be much faster than
using Streams.
was (Author: [email protected]):
Looking at the JBoss implementation I see that they are keeping track of the
LoggerContext in a Map with the ClassLoader as the key. Maybe JBoss can get
away with that but Log4j cannot. Instead, Log4j stores the LoggerContext in a
Map where the key is the identity hashcode of the ClassLoader. This should have
the same benefit with minimal extra overhead and won't run the risk of causing
ClassLoader leakage.
The comments for ClassLoaderContextSelector are "A log context selector which
chooses a log context based on the caller's classloader.", but that doesn't
seem to be what it does at all.
The algorithm JBoss seems to be using is:
# Call the JDK specific LogContextFinder passing in the Map of previously
located LogContexts and the LogContextFinder function (which just walks the
ClassLoader parent chain looking for the first LogContext it finds in the
ContextMap).
# Walks the StackFrames until it finds one whose class is associated with a
ClassLoader that can be found in the Map.
# If it doesn't find one it returns the default LogContext.
What really has me confused is I don't see any code that adds LogContext's to
the contextMap other than the registerLogContext method in
ClassLoaderContextSelector that IntelliJ says is never used. So it appears that
all this code ever does is return the default LogContext. Without some
algorithm to tell it to add a LogContext to the Map I don't see how the JBoss
code can be doing what it should be doing. I also don't see any tests in the
jboss-logging or jboss-logmanager projects to test this.
Am I misreading the code somehow?
I should contrast the algorithm that JBoss uses with the one Log4j uses:
# If the currentContext parameter is true then return the LoggerContext
associated with the ContextAnchor ThreadLocal. If one is not present the
default LoggerContext is returned.
# If the ClassLoader was specified locate the LoggerContext associated with
it, otherwise locate the caller's class (using StackLocatorUtil), get its
ClassLoader and locate the LoggerContext associated with it.
# To locate the LoggerContext check if the ClassLoader's identity is present
as a key in the contextMap. If it is return the LoggerContext. If not
recursively check its parents.
# Since no LoggerContext could be located, create a new one and register it
using the ClassLoader's identity as the key and return the created
LoggerContext.
After looking at the stack trace you provided I see that it isn't even in
Log4j's ClassLoaderContextSelector but the SLF4J adapter's getContext method.
It is trying to resolve the calling class to get its ClassLoader to pass to the
above algorithm. This probably shouldn't be handled this way because it you
have chosen to use a ContextSelector other than ClassLoaderContextSelect than
determining the caller's ClassLoader may be a waste of time. It should probably
just pass the FQCN.
> 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([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)
