Logger Lookup Much Slower and High CPU on JDK11

Environment

• OpenJDK 11
• Oracle JDK 11
• JBoss Enterprise Application Platform (EAP) 7.2

Issue

• The following code is much slower on JDK11 vs JDK8:

org.slf4j.LoggerFactory.getLogger(LoggerDemoResource.class)

• Analysis shows the increased time is in StackStreamFactory$AbstractStackWalker.fetchStackFrames(long, long, int, int, Object[]).

• Threads consuming cpu 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@11.0.5/Native Method)
	at java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames(java.base@11.0.5/StackStreamFactory.java:386)
	at java.lang.StackStreamFactory$AbstractStackWalker.getNextBatch(java.base@11.0.5/StackStreamFactory.java:322)
	at java.lang.StackStreamFactory$AbstractStackWalker.peekFrame(java.base@11.0.5/StackStreamFactory.java:263)
	at java.lang.StackStreamFactory$AbstractStackWalker.hasNext(java.base@11.0.5/StackStreamFactory.java:351)
	at java.lang.StackStreamFactory$StackFrameTraverser.tryAdvance(java.base@11.0.5/StackStreamFactory.java:593)
	at java.util.Spliterators$1Adapter.hasNext(java.base@11.0.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@11.0.5/StackStreamFactory.java:534)
	at java.lang.StackStreamFactory$AbstractStackWalker.doStackWalk(java.base@11.0.5/StackStreamFactory.java:306)

Resolution

• For performance improvement, keep any loggers as a static reference for reuse instead of frequently recreating and garbage collecting loggers.
• Upgrade to EAP 7.2.9 or 7.3.2+ for improvement
• If application has log4j configuration and using filter, see also the Using logging API causes high cpu and slower on JDK11 when application has log4j filter settings.

Root Cause

• This content is not included.java.lang.StackStreamFactory$AbstractStackWalker bad performance and high cpu
• This content is not included.Logger Lookup is much slower as with JDK 8
• This content is not included.LOGMGR-263
• This content is not included.Performance degradation with the LogContextSelector on Java 11
• Content from bugs.openjdk.java.net is not included.Content from bugs.openjdk.java.net is not included.https://bugs.openjdk.java.net/browse/JDK-8222942

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.