You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-user@logging.apache.org by Sean McCauliff <se...@gmail.com> on 2020/12/18 21:27:15 UTC

JDK 11 and StackWalker Performance Issue

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(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 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(java.base@11.0.8/Thread.java:834)

Re: JDK 11 and StackWalker Performance Issue

Posted by Ralph Goers <ra...@dslextreme.com>.
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 <se...@gmail.com> 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 <ck...@ckozak.net> 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(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 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(java.base@11.0.8/Thread.java:834)
>>> 
>> 



---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org


Re: JDK 11 and StackWalker Performance Issue

Posted by Sean McCauliff <se...@gmail.com>.
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 <ck...@ckozak.net> 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(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 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(java.base@11.0.8/Thread.java:834)
> >
>

Re: JDK 11 and StackWalker Performance Issue

Posted by Carter Kozak <ck...@ckozak.net>.
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(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 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(java.base@11.0.8/Thread.java:834)
> 

Re: JDK 11 and StackWalker Performance Issue

Posted by Ralph Goers <ra...@dslextreme.com>.
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 <ra...@dslextreme.com> 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 <se...@gmail.com> 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(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 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(java.base@11.0.8/Thread.java:834)
> 



---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org


Re: JDK 11 and StackWalker Performance Issue

Posted by Ralph Goers <ra...@dslextreme.com>.
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 <se...@gmail.com> 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(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 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(java.base@11.0.8/Thread.java:834)