Openj9: Performance of ManagementFactory.getRuntimeMXBeans is high on Java 11 and 12

[NottyCode]

Java -version output

openjdk version "12" 2019-03-19
OpenJDK Runtime Environment AdoptOpenJDK (build 12+33)
Eclipse OpenJ9 VM AdoptOpenJDK (build openj9-0.13.0, JRE 12 Mac OS X amd64-64-Bit Compressed References 20190320_32 (JIT enabled, AOT enabled)
OpenJ9 - caeb51f87
OMR - 33a33ff2
JCL - 419f571019 based on )

Summary of problem

Calls to ManagementFactory.getXXXMXBean are significantly more expensive on Java 11 & 12 than Java 8. Here are some example outputs (each item is time java Ut):

Java 8
```[email protected] uptime: 113
getMbean: 31
getName: 0
getUptime: 0

real 0m0.179s
user 0m0.175s
sys 0m0.054s

Java 11

[email protected] uptime: 274
getMbean: 138
getName: 1
getUptime: 0

real 0m0.360s
user 0m0.484s
sys 0m0.077s

Java 12

[email protected] uptime: 363
getMbean: 214
getName: 0
getUptime: 0

real 0m0.534s
user 0m0.512s
sys 0m0.155s

At first I thought this related to the class libraries, but when I run an adoptopenjdk hotspot build I get this output:

Java 12

[email protected] uptime: 231
getMbean: 63
getName: 46
getUptime: 1

real 0m0.305s
user 0m0.198s
sys 0m0.081s

It is possible that on hotspot the classes are being initialized sooner, but uptime (returned from the RuntimeMXBean.getUptime is higher in the OpenJ9 case and while that could be due to implementation details the time output from the shell suggests that OpenJ9 is taking much longer.

Diagnostic files
----------------

The test code

import java.lang.management.*;

public class Ut {

public static void main(String[] args) {
long st = System.currentTimeMillis();
RuntimeMXBean mbean = ManagementFactory.getRuntimeMXBean();
long st2 = System.currentTimeMillis();
String pid = mbean.getName();
long st3 = System.currentTimeMillis();
long ut = mbean.getUptime();
long st4 = System.currentTimeMillis();
System.out.println(pid + " uptime: " + ut);
System.out.println("getMbean: " + (st2 - st));
System.out.println("getName: " + (st3 - st2));
System.out.println("getUptime: " + (st4 - st3));
}
}
```

[pshipton]

@keithc-ca

[pshipton]

@vijaysun-omr

[sharon-wang]

I'm looking into this

[JasonFengJ9]

-verbose:init can break down the component loading time.

[andrewcraik]

So I have been looking at how the time breakdown in the initialization of the Management Beans breaks down in both Java 8 and Java 11 / 12. I'm still understanding the full cause for the increase, but there is a huge amount of time being spent generating lambdas and running lambdas as part of the initialization of the Management Beans infrastructure.

In Java 8 the time overhead points to https://github.com/eclipse/openj9/blob/c32212c83d472a0f839efeb3240013674f28ae05/jcl/src/java.management/share/classes/com/ibm/java/lang/management/internal/ManagementUtils.java#L394
This is registration of composite data handlers against bean types. Each registrant calls passing its class and, generally, :: which is syntactic sugar for the generation of a lambda to invoke the specified function. This seems to be where the time is being burned in the interpreter.

In Java 11/12 the infrastructure for handling the Management Beans seems to have been refactored to use more of the JCL infrastructure and I'm trying to understand where that specific increase has come from, but I'm not yet sure if there are more layers of lambdas and indirection involved or not.

[keithc-ca]

The map of converters is only used internally by tests (that don't need it): the plan is simply to remove all this unnecessary overhead in ManagementUtils.

[andrewcraik]

@vijaysun-omr FYI

[a7ehuo]

As per discussion with @vijaysun-omr, I ran the test code with openj9-0.14.0 for Java 8. getMbean is improved ~50% after #5477 from @keithc-ca.

0.12.1:   Avg upTime: 79.13 Avg getMbean: 21.53 Avg getName: 0 Avg getUptime: 0
0.14.0:   Avg upTime: 67.33 Avg getMbean: 9.70  Avg getName: 0 Avg getUptime: 0

Looking at the call stack. inside I:com/ibm/lang/management/internal/ExtendedRuntimeMXBeanImpl.<clinit>()V, most time is spent in
20.00 0 6 I:javax/management/NotificationBroadcasterSupport.<clinit>()V

Wondering if there is room for further improvement to eliminate it.

Release 0.14.0
[]-------------   2  1      0   0.00  30.00           0           9    I:java/lang/management/ManagementFactory.getRuntimeMXBean()Ljava/lang/management/RuntimeMXBean;
 +[]-----------   4  1      0   3.33   6.67           1           2    I:com/ibm/java/lang/management/internal/RuntimeMXBeanImpl.<init>()V
 | +[]---------   8  1      0   3.33   3.33           1           1    I:javax/management/ObjectName.construct(Ljava/lang/String;)V
 +[]-----------   3  1      0   0.00  23.33           0           7    I:com/ibm/lang/management/internal/ExtendedRuntimeMXBeanImpl.<clinit>()V
   +[]---------   6  1      0   3.33   3.33           1           1    N:java/lang/VMAccess.findClassOrNull(Ljava/lang/String;Ljava/lang/ClassLoader;)Ljava/lang/Class;
   +[]---------   4  1      0   0.00  20.00           0           6    I:javax/management/NotificationBroadcasterSupport.<clinit>()V
     +[]-------   5  1      0   3.33   3.33           1           1    I:com/sun/jmx/remote/util/ClassLogger.<clinit>()V
     +[]-------   5  1      0   0.00  16.67           0           5    I:com/sun/jmx/remote/util/ClassLogger.<init>(Ljava/lang/String;Ljava/lang/String;)V
       +[]-----  14  1      0   3.33   3.33           1           1    I:java/util/concurrent/ConcurrentHashMap.addCount(JI)V
       +[]-----   7  1      0   0.00  13.33           0           4    I:java/util/logging/Logger.demandLogger(Ljava/lang/String;Ljava/lang/String;Ljava/lang/Class;)Ljava/util/logging/Logger;
         +[]---   8  1      0   3.33   3.33           1           1    I:java/util/logging/LogManager.<clinit>()V
         +[]---  16  1      0   0.00  10.00           0           3    I:java/util/logging/LogManager$3.run()Ljava/lang/Void;
           +[]-  19  1      0   3.33   3.33           1           1    I:java/util/logging/LogManager.reset()V
           +[]-  17  1      0   3.33   3.33           1           1    I:sun/util/logging/PlatformLogger.<clinit>()V
           +[]-  32  1      0   3.33   3.33           1           1    I:java/util/HashMap.entrySet()Ljava/util/Set;

openjdk version "1.8.0_212"
OpenJDK Runtime Environment (build 1.8.0_212-b03)
Eclipse OpenJ9 VM (build openj9-0.14.0, JRE 1.8.0 Linux amd64-64-Bit Compressed References 20190417_286 (JIT enabled, AOT enabled)
OpenJ9   - bad1d4d06
OMR      - 4a4278e6
JCL      - 5590c4f818 based on jdk8u212-b03)

[pshipton]

@keithc-ca is investigating a performance improvement, to load fewer classes by default.

[pshipton]

Keith is making good progress, but the fix won't make the 0.15 release.