OpenJ9 startup performance on a Spring Boot application #5918
Comments
|
Also testing the performance with JDK8: openjdk version "1.8.0_212"
OpenJDK Runtime Environment (build 1.8.0_212-b04)
Eclipse OpenJ9 VM (build openj9-0.14.2, JRE 1.8.0 Windows 10 amd64-64-Bit Compressed References 20190521_368 (JIT enabled, AOT enabled)
OpenJ9 - 4b1df46fe
OMR - b56045d2
JCL - a8c217d402 based on jdk8u212-b04)And the startup time with args Then another try with JDK8 and args 21:45:31.391 [main] INFO c.y.p.application.Application - Started Application in 35.898 seconds (JVM running for 38.25) |
|
Here is the vlog file (changed the file type to |
Doesn't look like any AOT compilations happened :S. From the vlog: there isn't even any AOT code in the SCC, which is weird... Could you destroy the cache and run your program again, collecting the vlog both times? to destroy the cache, do |
I destroyed the cache by invoking: java -Xshareclasses:destroyAll -Xjit:verbose={compilePerformance},vlog=vlogbut this outputted an empty vlog file. However, the cache was deleted. Rerun with java -Xms256m -Xmx1G -Xshareclasses -Xjit:verbose={compilePerformance},vlog=vlogproduced this vlog: |
Sorry, I should've been more clear, I meant collecting the vlog for both invocations of your benchmark :). However, doesn't look like we need the second invocation; we didn't do any AOT compilations in that vlog...I don't know why :S. For the sake of sanity, could you do the following: I did this with And the vlog does show AOT compilations happening: This will verify that you're able to at least get AOT compilations going. |
|
I destroyed the cache and invoked java -Xshareclasses -Xjit:count=0,verbose={compilePerformance},vlog=C:/git/vlog -version
openjdk version "1.8.0_212"
OpenJDK Runtime Environment (build 1.8.0_212-b04)
Eclipse OpenJ9 VM (build openj9-0.14.2, JRE 1.8.0 Windows 10 amd64-64-Bit Compressed References 20190521_368 (JIT enabled, AOT enabled)
OpenJ9 - 4b1df46fe
OMR - b56045d2
JCL - a8c217d402 based on jdk8u212-b04)The only difference seems to be that I'm on Windows 10 host Here is the vlog of that: |
|
Ok, so looks like you did get AOT compilations when running so now the question becomes, why are there no AOT compilations when you run your benchmark.. |
|
Here is how my cache dir looks like: C:\Users\Jani\AppData\Local\javasharedresources>dir
Volume in drive C is OS
Volume Serial Number is F2BE-BE2C
Directory of C:\Users\Jani\AppData\Local\javasharedresources
28.05.2019 22.48 <DIR> .
28.05.2019 22.48 <DIR> ..
28.05.2019 11.50 314 572 800 C290M12F1A64P_sharedcc_Jani_G37
28.05.2019 22.48 314 572 800 C290M4F1A64P_sharedcc_Jani_G37
2 File(s) 629 145 600 bytes
2 Dir(s) 12 341 964 800 bytes free |
|
Ok, just for the sake of doing a second sanity, and also to get a sense of how much perf could improve, could you do the following: |
|
I think the key lies in the large number of compilation failures. A quick glance at the vlog shows many "compilationIlGenFailure". We need to understand the reason of that. I'll look at the code. |
|
There's 200 failures out of ~2900 methods, but that doesn't explain why methods like |
|
There are many possible reasons why the JIT throws ILGenFailure |
|
@dsouzai Can you update the script to give the total time spent in failed compilations? |
|
The script already prints that out, eg: |
|
ah, ok. Looked straight past that. Thanks. |
|
The problem with compilationIlGenFailures is that compilations are not retried, so the methods subject to these failures will run interpreted for the entire duration of the JVM. This could lead to severe slowdowns depending on the importance of these methods. |
|
That fits - the 10x deficit made me wonder if we were running in the interpreter. If we fail some hot methods it would be similar. |
Please find attached here both vlogs: |
Here are the prints from stderr: Compilation Failed Because: IL Gen Failure
Compilation Failed Because: IL Gen Failure
Compilation Failed Because: IL Gen Failure
Compilation Failed Because: IL Gen Failure
Compilation Failed Because: IL Gen Failure
Compilation Failed Because: IL Gen Failure
Compilation Failed Because: IL Gen Failure
... (totaling 168 hits)
Compilation Failed Because: FSD_HAS_INVOKEHANDLE 0
... (totaling 18 hits)
Compilation Failed Because: FSD_HAS_INVOKEHANDLE 2 |
|
What did the perf look like for the run that produced vlog2? Looks like the majority of failures were due to AOT relocations when doing |
|
are you running with an agent attached by any chance for debugging purposes? Because that might explain why there's no AOT happening (when we don't specify |
|
First run (vlog1): 23:39:14.749 [main] INFO c.y.p.application.Application - Started Application in 44.284 seconds (JVM running for 47.72)Second run (vlog2): 23:39:59.526 [main] INFO c.y.p.application.Application - Started Application in 32.227 seconds (JVM running for 33.905) |
Yes, that is actually true! I should have stated that in the beginning that I was using Visual Studio Code for the first vlogs and it attaches a debugger. The vlog1 and vlog2 was then purely with cmd and no debuggers attached or anything. Sorry about this, I should have mentioned about this in the setup. |
|
But without the debugger attached I wasn't able to get any output to stderr with |
|
Ahh ok, that at least explains why there was no AOT before. For the sake a comparison to allow OpenJ9 to get the benefit of AOT heh, would you mind doing a run without the debugger :). ie:
Thanks! |
|
Here is one more vlog no debuggers attached and with args: vlog-new.20190529.000410.16028.txt Also, with the shareclasses populated on previous runs the result of the "benchmark" is now ~31s (compared to ~16s with HotSpot): 00:04:43.525 [main] INFO c.y.p.application.Application - Started Application in 31.485 seconds (JVM running for 33.054) |
|
Haha beat me to it :) |
|
I wonder why this test shows so much more impact - maybe Spring boot brings in a larger number of jars? -- looks like the whole app is in only one jar on the filesystem which is spring.boot.openj9-0.0.1-SNAPSHOT.jar. That jar contains 157 jars inside it, but it wouldn't make sense to be checking timestamps of those would it? There seems to be an element of mystery here. edit 2, delta is still reproducible, a solid 30% from disabling timestamp checks. edit 3: -verbose indicates we load 9072 classes during startup for this app, I can't imagine that's a lot more than a typical liberty test case, but it would be interesting to know what that number is. |
|
I was also able to reproduce a big win on Linux launching this spring application by adding the noTimestampChecks. I definitely think this is something we should investigate further! With |
|
Originally the jar of jar files did not work with |
|
We only check the timestamp of the outside most jar, which is spring.boot.openj9-0.0.1-SNAPSHOT.jar in this case. But we are checking this every time class is loaded from the shared cache. (If the JCL patch is added back, this check would only happen once I believe) |
|
Probably on the VM side, we can change the default behavior to do timestamp check only once for each jar and introduce a new option "forceTimestampChecks" which does timestamp check on every load. @pshipton |
|
Looking at the code, it looks like there's a need to add the concept of time-last-checked and the ability to specify an interval between checks. Checking the same jar timestamp at micro-second resolution makes little sense, particularly when walking the classpath and everything is coming from the same jar file. |
|
If I recall correctly, many of the design decisions for timestamp checking came about from supporting the SCC in development scenarios when you want to be sure you're running the very latest version of the code you just wrote. |
|
Wouldn't that require a mechanism to monitor the FS and pro-actively unload jitted code? |
|
That would be a further improvement / different feature. This was to ensure that we picked the most recent version of the class available. |
|
We don't really "monitor" the FS, we do timestamp check (when necessary) before returning class from the shared cache. Not sure about jitted code, but for classes, if any JVM connecting to the shared cache detects an updated jar, we will mark all potentially stale classes in the shared cache as stale pessimistically. When we later know the class is not actually updated we will remove the stale marking. |
Wouldn't that be equivalent (in a non SCC run) to a JVM loading classes, and then someone modified the jars on disk? I don't think the currently running JVM is expected to now start using the updated jars is it? I would've thought that it just affected the next JVM instance. |
|
Yes, that's where I was heading. I don't think we can be sure that we're running the very latest version of the code, so it probably doesn't matter to anyone if we only check for updates every 100ms instead of on every class load. |
if classes are modified and we get some from the cache and some from the jar, they may not be compatible with each other |
|
What has been described so far certainly doesn't prevent that case. |
|
File timestamps are not atomically updated and are not guaranteed to be updated for any given file update. Given the limited resolution of operating system timers and the aforementioned limitations of timestamps no scheme based on timestamp checking can ensure a file read twice at two different points in time is actually the same file. |
|
@pshipton and I have been discussing alternative approaches. There is a tentative design being considered but it needs more discussion in particular input from @hangshao0 is needed. This will be updated when that design has been fleshed out more. |
|
Peter just discussed with me. In Java 11+, we can get the jar file open information from the class loader rather than using the JCL zip_hook. Since this change may not make it to the 0.15.0 release, we can change the code to check the timestamp only once for each jar during the startup phase for the 0.15.0 release. This will at least partially solve this problem for 0.15.0. Later with jar file open info from class loader, this issue should be fully solved. |
|
Moving this to |
DanHeidinga
modified the milestones:
Release 0.15 (Java 8, 11, 12) July refresh,
Release 0.16 (Java 13)
|
This should be resolved now by #6174 |
pshipton
modified the milestones:
Release 0.16 (Java 13),
Release 0.15 (Java 8, 11, 12) July refresh
|
Fixed for the 0.15 release via #6401 |
Java -version output
Summary of problem
I'm experimenting with both AdoptOpenJDK and openJ9 but I'm having weirdly poor performance with our Spring Boot based application in comparison to OpenJDK and HotSpot.
The exact version of AdoptOpenJDK is:
And the version of OpenJDK is:
I know the following results are not real benchmarks or anything but just to give an idea of the magnitude how much slower the openJ9 is in comparison.
With HotSpot:
And then with openJ9:
I am launching the openJ9 version with flags
-Xms256m -Xmx1G -Xshareclasses -Xquickstart.Also, partial output of
systeminfocmd:$ systeminfo Host Name: xxx OS Name: Microsoft Windows 10 Pro OS Version: 10.0.17763 N/A Build 17763 OS Manufacturer: Microsoft Corporation OS Configuration: Standalone Workstation OS Build Type: Multiprocessor Free Registered Owner: Jani Registered Organization: Microsoft Product ID: 00330-80000-00000-AA476 Original Install Date: 21.2.2019, 16.44.02 System Boot Time: 28.5.2019, 21.27.11 System Manufacturer: Dell Inc. System Model: XPS 15 9550 System Type: x64-based PC Processor(s): 1 Processor(s) Installed. [01]: Intel64 Family 6 Model 94 Stepping 3 GenuineIntel ~2601 Mhz BIOS Version: Dell Inc. 1.3.0, 11.8.2017 Windows Directory: C:\WINDOWS System Directory: C:\WINDOWS\system32 Boot Device: \Device\HarddiskVolume1 System Locale: en-us;English (United States) Input Locale: fi;Finnish Time Zone: (UTC+02:00) Helsinki, Kyiv, Riga, Sofia, Tallinn, Vilnius Total Physical Memory: 32 630 MB Available Physical Memory: 23 378 MB Virtual Memory: Max Size: 44 553 MB Virtual Memory: Available: 34 241 MB Virtual Memory: In Use: 10 312 MB Page File Location(s): C:\pagefile.sysAny tips or pointers what could be wrong with my setup here? Thanks!
The text was updated successfully, but these errors were encountered: