Re: JDK 11 and StackWalker Performance Issue

First, you don’t need to file an issue as it would be closed as a duplicate of LOG4J2-2940. Second, LOG4J2-2537 has nothing to do with this issue. 

Ralph

> On Dec 18, 2020, at 3:05 PM, Sean McCauliff <[email protected]> wrote:
> 
> Before I go and file a ticket is this ticket related to this problem?
> https://issues.apache.org/jira/browse/LOG4J2-2537  I don't have that
> warning on the application output however.
> 
> log4j2 version is 2.13.1
> 
> 
> On Fri, Dec 18, 2020 at 1:41 PM Carter Kozak <[email protected]> wrote:
> 
>> If we made a change that results in degraded performance, we should
>> investigate and fix it. I imagine this would have an impact on application
>> startup time even if all loggers are loaded once as static fields.
>> 
>> Can you confirm the log4j2 version that you're using in this example?
>> It appears that logger instances are not stored, but instead requested
>> from the context as needed. The process of loading a logger is meant to be
>> potentially more expensive than subsequent uses (we want to front-load work
>> so that each event logged later is less expensive), so minimizing calls to
>> LogManager/LoggerFactory.getLogger is ideal regardless of other factors.
>> 
>> Would you mind filing a jira ticket for this?
>> 
>> Thanks,
>> Carter
>> 
>> On Fri, Dec 18, 2020, at 16:27, Sean McCauliff 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)
>>> 
>>