In the cloud environment, you need to bring up your microservices applications quickly and frequently in respond to user demands. Therefore, having a JVM that starts up faster is important. Eclipse OpenJ9 is a JVM that has a fast start-up performance and a low memory footprint. This post outlines how to improve the start-up performance of Payara Micro on OpenJ9.
OpenJ9 has a feature called class data sharing which enables the J9 JVM to store class data and dynamic Ahead of Time (AOT) compiled code into a shared cache. Subsequent JVMs can directly load existing class data and AOT from the shared cache, resulting in a better start-up performance. As the cache can be shared across multiple JVMs, you get memory savings. On the cloud, you pay for the memory you used.
In a previous post, we announced the class sharing support for fat jars; thus OpenJ9 class sharing also support running Payara Micro. With the correct option –-unpackdir and noTimestampChecks, the start-up performance of Payara Micro can be largely improved.
Example running Payara Micro on OpenJ9
In this example, we will run Payara Mirco with two sets of command line options and compare the results.
Case 1: run with the -Xshareclasses with cache name only
For most applications, shared class should work out-of-box simply using -Xshareclasses in the command line. It is recommended that you always specify a cache name for your application. In this example, we use “payara” as the cache name.
Simply run -Xshareclasses:name=payara. The cold run (populating a new share cache) result is:
java -Xshareclasses:name=payara -Xscmx50m -jar payara-micro-5.193.jar --noCluster --addlibs ./hsqldb-2.2.8.jar/hsqldb-2.2.8.jar … [2019-10-17T16:39:44.315-0400] [] [INFO] [] [PayaraMicro] [tid: _ThreadID=1 _ThreadName=main] [timeMillis: 1571344784315] [levelValue: 800] Payara Micro 5.193 #badassmicrofish (build 252) ready in 12,257 (ms)
Payara Micro finished starting up after 12,257ms.
The cache statistics are:
java -Xshareclasses:name=payara,printStats Current statistics for cache "payara": Cache created with: -Xnolinenumbers = false BCI Enabled = true Restrict Classpaths = false Feature = cr Cache contains only classes with line numbers base address = 0x00007F20E474F000 end address = 0x00007F20E78F9000 allocation pointer = 0x00007F20E5685630 cache size = 52428192 softmx bytes = 52428192 free bytes = 15869824 Reserved space for AOT bytes = -1 Maximum space for AOT bytes = -1 Reserved space for JIT data bytes = -1 Maximum space for JIT data bytes = -1 Metadata bytes = 750064 Metadata % used = 2% Class debug area size = 4165632 Class debug area used bytes = 2713512 Class debug area % used = 65% ROMClass bytes = 15951408 AOT bytes = 15168016 JIT data bytes = 171480 Zip cache bytes = 0 Startup hint bytes = 120 Data bytes = 351648 # ROMClasses = 6634 # AOT Methods = 3023 # Classpaths = 5 # URLs = 0 # Tokens = 0 # Zip caches = 0 # Startup hints = 1 # Stale classes = 0 % Stale classes = 0% Cache is 69% full Cache is accessible to current user = true
Now we have a populated shared cache. Run again with the warm cache, the result is:
java -Xshareclasses:name=payara -Xscmx50m -jar payara-micro-5.193.jar --noCluster --addlibs ./hsqldb-2.2.8.jar/hsqldb-2.2.8.jar ... [2019-10-17T16:40:43.923-0400] [] [INFO] [] [PayaraMicro] [tid: _ThreadID=1 _ThreadName=main] [timeMillis: 1571344843923] [levelValue: 800] Payara Micro 5.193 #badassmicrofish (build 252) ready in 6,091 (ms)
We can see the start-up time reduced to 6,091ms, as we benefit from the existing data in the shared cache.
The cache statistics are:
java -Xshareclasses:name=payara,printStats=classpath … /tmp/payaramicro-rt1176736565645219013tmp/runtime/weld-integration-fragment.jar /tmp/payaramicro-rt1176736565645219013tmp/runtime/work-management.jar /tmp/payaramicro-rt1176736565645219013tmp/runtime/wrapper.jar /tmp/payaramicro-rt1176736565645219013tmp/runtime/yasson.jar /team/hangshao/./hsqldb-2.2.8.jar/hsqldb-2.2.8.jar Current statistics for cache "payara": Cache created with: -Xnolinenumbers = false BCI Enabled = true Restrict Classpaths = false Feature = cr Cache contains only classes with line numbers base address = 0x00007F1400E56000 end address = 0x00007F1404000000 allocation pointer = 0x00007F1401DA9FC8 cache size = 52428192 softmx bytes = 52428192 free bytes = 15135656 Reserved space for AOT bytes = -1 Maximum space for AOT bytes = -1 Reserved space for JIT data bytes = -1 Maximum space for JIT data bytes = -1 Metadata bytes = 1068940 Metadata % used = 2% Class debug area size = 4165632 Class debug area used bytes = 2714532 Class debug area % used = 65% ROMClass bytes = 16072648 AOT bytes = 15459172 JIT data bytes = 174256 Zip cache bytes = 0 Startup hint bytes = 240 Data bytes = 351648 stale bytes = 0 # ROMClasses = 10265 # AOT Methods = 3051 # Classpaths = 8 # URLs = 0 # Tokens = 0 # Zip caches = 0 # Startup hints = 2 # Stale classes = 0 % Stale classes = 0% Cache is 71% full Cache is accessible to current user = true
Comparing the # ROMClasses in the cache statistics between the cold run and warm run, it is interesting to see there are > 3,000 additional rom classes added to the shared cache. # Classpaths increased from 5 to 8.
Digging into it further, it was determined that Payara unzipped the fat jar payara-micro-5.193.jar into the /tmp folder and loaded the classes from the unzipped jars under the /tmp folder. For example, the class path shown in the cache statistics:/tmp/payaramicro-rt1176736565645219013tmp/runtime/yasson.jar. The string “rt1176736565645219013tmp” in the directory name changes from run to run, which causes a problem for the shared classes cache – when a class loader asks the shared cache for a class, the cached class won’t be returned as the class path is changed. As a result, the class loader goes to the jars under /tmp to search for the class and tries storing the same class to the shared cache again. The JVM then notices that there is an exact match in the shared cache, so it returns the one in the shared cache. Even though the class in the shared cache is being used, one more new metadata for the same class pointing to the new class path is stored to the shared cache. That is why we see from the cache statistics that # ROMClasses in metadata increased > 3000, but the ROMClass bytes does not increase much. Also new class paths are added to the shared cache.
The following example shows how to solve the issue described above.
Case 2: run with the --unpackdir and noTimestampChecks
Looking at here, Payara has an option --unpackdir to specify the unpack directory of the fat jar. So using --unpackdir can avoid the inconsistent class paths issue.
In addition, J9 JVM checks timestamps of the jar files to make sure there is no updated version before a class is returned from the shared cache. Unfortunately, the class loader in Payara Mirco will update the timestamps of the unzipped jars. However, as all the classes are from the same fat jar payara-micro-5.193.jar, the classes are the same between runs. So we can run with -Xshareclasses sub-option noTimestampChecksto turn off the unnecessary timestamp checks.
The result of warm run using --unpackdir and noTimestampChecks
java -Xshareclasses:name=payara,noTimestampChecks -Xscmx50m -jar payara-micro-5.193.jar --unpackdir ./unpack/ --noCluster --addlibs ./hsqldb-2.2.8.jar/hsqldb-2.2.8.jar [2019-10-17T17:08:27.508-0400] [] [INFO] [] [PayaraMicro] [tid: _ThreadID=1 _ThreadName=main] [timeMillis: 1571346507508] [levelValue: 800] Payara Micro 5.193 #badassmicrofish (build 252) ready in 3,798 (ms)
The Cache statistics are:
java -Xshareclasses:name=payara,printStats Current statistics for cache "payara": Cache created with: -Xnolinenumbers = false BCI Enabled = true Restrict Classpaths = false Feature = cr Cache contains only classes with line numbers base address = 0x00007F1400E56000 end address = 0x00007F1404000000 allocation pointer = 0x00007F1401DC67F8 cache size = 52428192 softmx bytes = 52428192 free bytes = 13971268 Reserved space for AOT bytes = -1 Maximum space for AOT bytes = -1 Reserved space for JIT data bytes = -1 Maximum space for JIT data bytes = -1 Metadata bytes = 848980 Metadata % used = 2% Class debug area size = 4165632 Class debug area used bytes = 2720320 Class debug area % used = 65% ROMClass bytes = 16189432 AOT bytes = 16550016 JIT data bytes = 350976 Zip cache bytes = 0 Startup hint bytes = 240 Data bytes = 351648 # ROMClasses = 6693 # AOT Methods = 3176 # Classpaths = 5 # URLs = 0 # Tokens = 0 # Zip caches = 0 # Startup hints = 2 # Stale classes = 0 % Stale classes = 0% Cache is 73% full Cache is accessible to current user = true
We can see the # ROMClasses is still about 6600 and # Classpaths is still 5. Compared to case 1, The start-up time of warm run dropped from 6,091ms to 3,798ms, a more than 37% improvement.
Conclusion
As we can see from the above results, the best practice to run Payara Micro on OpenJ9 is to turn on option –-unpackdir for Payara Micro and noTimestampChecks for OpenJ9 JVM (unless you are updating the classes in the jars).
If you want to try Payara Micro on OpenJ9, you can get the pre-built OpenJ9 binaries at AdoptOpenJDK. Visit our website if you want to learn more about OpenJ9.
Great blog. Try it with –nocluster to cut out the Hazelcast cluster networking boot time. I got sub-second boot time. Payara Micro 5 #badassmicrofish (build ${build.number}) ready in 937 (ms)
Nice result !