Bug 1813436

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.

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?

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.

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.

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.