RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1813436 - java.lang.StackStreamFactory$AbstractStackWalker bad performance and high cpu
Summary: java.lang.StackStreamFactory$AbstractStackWalker bad performance and high cpu
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: java-11-openjdk
Version: 8.4
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: rc
: 8.0
Assignee: Aleksey Shipilev
QA Contact: OpenJDK QA
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-03-13 19:42 UTC by Mike Millson
Modified: 2023-10-06 19:25 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2021-09-30 18:24:43 UTC
Type: Bug
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
Reproducer (4.65 KB, application/zip)
2020-03-13 20:03 UTC, Mike Millson
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker JBEAP-18947 0 Major Verified [GSS](7.2.z) LOGMGR-263 - Logger Lookup is much slower as with JDK 8 2020-12-03 17:57:55 UTC
Red Hat Issue Tracker LOGMGR-263 0 Critical Resolved Logger Lookup is much slower as with JDK 8 2020-12-03 17:57:55 UTC
Red Hat Knowledge Base (Solution) 4901011 0 None None None 2020-03-13 20:17:58 UTC
openjdk bug system JDK-8222942 0 None None None 2020-03-13 20:22:54 UTC

Description Mike Millson 2020-03-13 19:42:43 UTC
Customers migrating applications on JBoss EAP7.2 to JDK11 are hitting bad performance and high cpu due to StackStreamFactory$AbstractStackWalker.

The increased time is in StackStreamFactory$AbstractStackWalker.fetchStackFrames(long, long, int, int, Object[]).

High cpu threads have the following stack trace:
"default task-3013" #3711 prio=5 os_prio=0 cpu=4592.93ms elapsed=6.92s tid=0x0000000009565800 nid=0x5210 runnable  [0x00007f79eaf0f000]
   java.lang.Thread.State: RUNNABLE
    at java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames(java.base.5/Native Method)
    at java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames(java.base.5/StackStreamFactory.java:386)
    at java.lang.StackStreamFactory$AbstractStackWalker.getNextBatch(java.base.5/StackStreamFactory.java:322)
    at java.lang.StackStreamFactory$AbstractStackWalker.peekFrame(java.base.5/StackStreamFactory.java:263)
    at java.lang.StackStreamFactory$AbstractStackWalker.hasNext(java.base.5/StackStreamFactory.java:351)
    at java.lang.StackStreamFactory$StackFrameTraverser.tryAdvance(java.base.5/StackStreamFactory.java:593)
    at java.util.Spliterators$1Adapter.hasNext(java.base.5/Spliterators.java:681)
    at org.jboss.logmanager.JDKSpecific$FindAllWalkFunction.apply(JDKSpecific.java:208)
    at org.jboss.logmanager.JDKSpecific$FindAllWalkFunction.apply(JDKSpecific.java:198)
    at java.lang.StackStreamFactory$StackFrameTraverser.consumeFrames(java.base.5/StackStreamFactory.java:534)
    at java.lang.StackStreamFactory$AbstractStackWalker.doStackWalk(java.base.5/StackStreamFactory.java:306)

The main use case we are seeing is logging, and we have been able to work around many issues by making loggers static; however, it is expected that many customers will have code that cannot easily be changed, and this bottleneck will prevent them from moving to JDK11.

Comment 1 Mike Millson 2020-03-13 20:03:03 UTC
Created attachment 1669981 [details]
Reproducer

Steps to reproduce the issue:
1) Deploy attached logger-demo.war to JBoss EAP 7.2.
2) Hit the following URL: http://localhost:8080/logger-demo/slf4j
3) Deploy using both JDK8 and JDK11, and you will see the time to instantiate 10,000 loggers is much higher in JDK11 vs. JDK8. On my box, it was ~5 secs for JDK11 and ~1 sec for JDK8.

Comment 2 Aleksey Shipilev 2020-03-23 12:43:06 UTC
With the reproducer and 11.0.7-ea, VisualVM shows this hotpath:

 com.example.demo.LoggerDemoResource.getHelloWorldJSON()
 org.slf4j.LoggerFactory.getLogger()
 org.slf4j.LoggerFactory.getLogger()
 org.slf4j.impl.Slf4jLoggerFactory.getLogger()
 org.jboss.logmanager.LogContext.getLogContext()
 org.jboss.as.logging.logmanager.WildFlyLogContextSelectorImpl.getLogContext()
 org.jboss.logmanager.ThreadLocalLogContextSelector.getLogContext()
 org.jboss.logmanager.ClassLoaderLogContextSelector.getLogContext()
 java.security.AccessController.doPrivileged[native]()
 org.jboss.logmanager.ClassLoaderLogContextSelector$1.run()
 org.jboss.logmanager.ClassLoaderLogContextSelector$1.run()
 org.jboss.logmanager.JDKSpecific.findCallingClasses()
 java.lang.StackWalker.walk()
 java.lang.StackStreamFactory$AbstractStackWalker.walk()
 java.lang.StackStreamFactory$AbstractStackWalker.beginStackWalk()
 java.lang.StackStreamFactory$AbstractStackWalker.callStackWalk[native]()
 java.lang.StackStreamFactory$AbstractStackWalker.doStackWalk()
 java.lang.StackStreamFactory$StackFrameTraverser.consumeFrames()
 org.jboss.logmanager.JDKSpecific$FindAllWalkFunction.apply()
 org.jboss.logmanager.JDKSpecific$FindAllWalkFunction.apply()
 java.util.Spliterators$1Adapter.hasNext()
 java.lang.StackStreamFactory$StackFrameTraverser.tryAdvance()
 java.lang.StackStreamFactory$AbstractStackWalker.hasNext()
 java.lang.StackStreamFactory$AbstractStackWalker.peekFrame()
 java.lang.StackStreamFactory$AbstractStackWalker.getNextBatch()
 java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames()
 java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames[native]()

AbstractStackWalker.fetchStackFrames enters JVM code at JVM_MoreStackWalk. 

perf record -g shows this:

   - 35.44% JVM_MoreStackWalk
      - 34.79% StackWalk::fetchNextBatch
         - 33.81% StackWalk::fill_in_frames
            - 24.13% JavaFrameStream::fill_frame
               - 22.46% java_lang_StackFrameInfo::set_method_and_bci
                  - 15.54% CallInfo::CallInfo
                     - 11.25% CallInfo::set_resolved_method_name
                        - 7.13% java_lang_invoke_ResolvedMethodName::find_resolved_method
                             4.86% ResolvedMethodTable::lookup
                             0.71% oopDesc::address_field
                             0.63% AccessInternal::PostRuntimeDispatch<G1BarrierSet::AccessBarrier<1187956ul, G1BarrierSet>, (AccessInternal::BarrierType)2, 1187956ul>::oop_access_barrier
                          2.37% ResolvedMethodTable::find_method
                       0.99% methodHandle::operator=
                       0.90% methodHandle::~methodHandle
                  - 3.23% MethodHandles::init_method_MemberName
                       0.92% AccessInternal::PostRuntimeDispatch<G1BarrierSet::AccessBarrier<573558ul, G1BarrierSet>, (AccessInternal::BarrierType)1, 573558ul>::oop_access_barrier
                       0.53% methodHandle::methodHandle
                    0.93% methodHandle::~methodHandle
            - 7.15% JavaFrameStream::next
               - 4.52% frame::sender
                  - 2.85% frame::sender_for_interpreter_frame
                     - 2.17% CodeCache::find_blob
                          0.80% CodeHeap::find_blob_unsafe
                    0.69% CodeCache::find_blob

This StackWalker codepath can be captured with the targeted microbenchmark. The underlying issue seems to be construction of java.lang.StackFrameInfo that involves look ups in internal JVM hashtables.

I shall see if this can be mitigated on JDK side. But really, walking the stack on every logger instantiation sounds dubious, and probably calls for caching on application/library side?

Comment 3 Aleksey Shipilev 2020-03-23 13:00:58 UTC
Looking at the source here:
 https://github.com/jboss-logging/jboss-logmanager/blob/master/core/src/main/java9/org/jboss/logmanager/JDKSpecific.java#L67

It seems it would use FindAllWalkFunction to walk the entire stack looking for classes. This would cost proportional to stack trace depth. JDK fixes could probably mitigate this by a constant factor, but otherwise it would still be costly. The fun thing is that JDKSpecific.findCallingClasses is called from here:
 https://github.com/jboss-logging/jboss-logmanager/blob/master/core/src/main/java/org/jboss/logmanager/ClassLoaderLogContextSelector.java#L91

    private final PrivilegedAction<LogContext> logContextAction = new PrivilegedAction<LogContext>() {
        public LogContext run() {
            final Collection<Class<?>> callingClasses = JDKSpecific.findCallingClasses(logApiClassLoaders);
            for (Class<?> caller : callingClasses) {
                final LogContext result = check(caller.getClassLoader());
                if (result != null) {
                    return result; // <--- select the first LogContext with valid classloader?
                }
            }
            return defaultSelector.getLogContext();
        }

So, we walk the entire stack with StackWalker, get the entire collection of classes, and then pick off the first one we want?
Instead, ClassLoaderLogContextSelector should ask JDKSpecific to get it the first class that matches its criteria, so we don't do the entire stack walk.

Comment 4 Aleksey Shipilev 2020-03-23 13:06:15 UTC
In other words, like looks like jboss-logmanager performance issue.

I shall go and see if we can make it less painful on JDK side too, though.

Comment 5 Aleksey Shipilev 2020-03-23 13:27:10 UTC
Note, JDK 8 and JDK 11 must be running different code from Multi-Release jboss-logmanager:
 JDK 8: SecurityManager.getClassContext(), which calls into JVM_GetClassContext, which pulls the klass mirrors out of vframeStream directly;
 JDK 9+: StackWalker, which goes through constructing StackFrameInfo objects, etc.


Note You need to log in before you can comment on or make changes to this bug.