Re: JDK 11 and StackWalker Performance Issue

Also, we should a) investigate whether we can a) use StackWalker.getCallerClass() directly in LoggerFactory.getLogger() as that method is supposed to be much faster than walking the stack and b) check to see what the overhead of that is. We may also want to add a method to LogManager to determine if the ContextSelector requires the ClassLoader, in which case we could skip the call.

Ralph

> On Dec 18, 2020, at 3:03 PM, Ralph Goers <[email protected]> wrote:
> 
> This looks like the same issue as https://issues.apache.org/jira/browse/LOG4J2-2940 <https://issues.apache.org/jira/browse/LOG4J2-2940>. The ClassLoaderContextSelector needs to find the caller’s class to determine which LoggerContext the Logger should be attached to.  If you don’t want to have multiple LoggerContext’s then you can configure Log4j to use a different ContextSelector such as the BasicContextSelector (see http://logging.apache.org/log4j/2.x/manual/extending.html <http://logging.apache.org/log4j/2.x/manual/extending.html>).
> 
> That said, there is a bug here as even if you choose a different ContextSelector the slf4j LoggerFactory is still trying to locate the caller to determine the ClassLoader to pass to LogManager’s getContext method. That should only happen if it is required.
> 
> Ralph
> 
> 
>> On Dec 18, 2020, at 2:27 PM, Sean McCauliff <[email protected]> wrote:
>> 
>> There are many threads in our Kafka server performing logging.  Their
>> stacks look like the stack trace below.  I see from other email threads
>> that java.lang.StackWalker in JDK 11 is not as performant as the old sun.*
>> classes that are used for the same functionality.
>> 
>> Since this is logged at debug level and I'm not seeing this in my logs why
>> does StackWalker need to be called?
>> 
>> "data-plane-kafka-request-handler-5" #187 daemon prio=5 os_prio=0
>> cpu=128019254.19ms elapsed=340579.66s tid=0x00007fe3092e1800 nid=0x2be4
>> runnable  [0x00007fd58c9f5000]
>>  java.lang.Thread.State: RUNNABLE
>>       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 kafka.utils.Logging.logger(Logging.scala:43)
>>       at kafka.utils.Logging.logger$(Logging.scala:43)
>>       at
>> kafka.server.IncrementalFetchContext.logger$lzycompute(FetchSession.scala:400)
>>       - locked <0x00000005f016f650> (a
>> kafka.server.IncrementalFetchContext)
>>       at
>> kafka.server.IncrementalFetchContext.logger(FetchSession.scala:400)
>>       at kafka.utils.Logging.debug(Logging.scala:62)
>>       at kafka.utils.Logging.debug$(Logging.scala:62)
>>       at
>> kafka.server.IncrementalFetchContext.debug(FetchSession.scala:400)
>>       at
>> kafka.server.IncrementalFetchContext.updateAndGenerateResponseData(FetchSession.scala:482)
>>       - locked <0x00000002632d0d70> (a kafka.server.FetchSession)
>>       at
>> kafka.server.KafkaApis.processResponseCallback$1(KafkaApis.scala:769)
>>       at
>> kafka.server.KafkaApis.$anonfun$handleFetchRequest$29(KafkaApis.scala:833)
>>       at
>> kafka.server.KafkaApis.$anonfun$handleFetchRequest$29$adapted(KafkaApis.scala:833)
>>       at
>> kafka.server.KafkaApis$$Lambda$2090/0x0000000800ffb040.apply(Unknown Source)
>>       at
>> kafka.server.ReplicaManager.fetchMessages(ReplicaManager.scala:963)
>>       at kafka.server.KafkaApis.handleFetchRequest(KafkaApis.scala:835)
>>       at kafka.server.KafkaApis.handle(KafkaApis.scala:130)
>>       at
>> kafka.server.KafkaRequestHandler.run(KafkaRequestHandler.scala:70)
>>       at java.lang.Thread.run([email protected]/Thread.java:834)
>