JDK-8253127 : AOT: vmTestbase/jit/tiered/Test.java failed with "RuntimeException: '^[0-9.]+: \\[compile level=\\d' missing from stdout"
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 16
  • Priority: P4
  • Status: Closed
  • Resolution: Won't Fix
  • OS: linux
  • CPU: x86_64
  • Submitted: 2020-09-14
  • Updated: 2021-01-28
  • Resolved: 2021-01-28
Related Reports
Relates :  
JDK-8251462 - Simplify compilation policy
Relates :  
JDK-8244778 - Archive full module graph in CDS
Description
The following test failed in the JDK16 CI:

vmTestbase/jit/tiered/Test.java

Here's a snippet from the log file:

----------System.out:(7/2810)----------
TieredCompilation is enabled
Command line: [/opt/mach5/mesos/work_dir/jib-master/install/jdk-16+16-662/linux-x64-debug.jdk/jdk-16/fastdebug/bin/java -cp /opt/mach5/mesos/work_dir/slaves/52628e90-e5e7-4ef3-af97-10d8776d10db-S2289/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/3befb8b8-5446-4dac-8bf7-61c944e0d3cb/runs/5e44fd80-642d-4ad1-8c57-7d0c5635cecb/testoutput/test-support/jtreg_open_test_hotspot_jtreg_vmTestbase_vm_compiler/classes/2/vmTestbase/jit/tiered/Test.d:/opt/mach5/mesos/work_dir/jib-master/install/jdk-16+16-662/src.full/open/test/hotspot/jtreg/vmTestbase/jit/tiered:/opt/mach5/mesos/work_dir/slaves/52628e90-e5e7-4ef3-af97-10d8776d10db-S2289/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/3befb8b8-5446-4dac-8bf7-61c944e0d3cb/runs/5e44fd80-642d-4ad1-8c57-7d0c5635cecb/testoutput/test-support/jtreg_open_test_hotspot_jtreg_vmTestbase_vm_compiler/classes/2/vmTestbase:/opt/mach5/mesos/work_dir/slaves/52628e90-e5e7-4ef3-af97-10d8776d10db-S2289/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/3befb8b8-5446-4dac-8bf7-61c944e0d3cb/runs/5e44fd80-642d-4ad1-8c57-7d0c5635cecb/testoutput/test-support/jtreg_open_test_hotspot_jtreg_vmTestbase_vm_compiler/classes/2/test/lib:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/5.1/b01/bundles/jtreg_bin-5.1.zip/jtreg/lib/javatest.jar:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/5.1/b01/bundles/jtreg_bin-5.1.zip/jtreg/lib/jtreg.jar:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/5.1/b01/bundles/jtreg_bin-5.1.zip/jtreg/lib/junit.jar:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/5.1/b01/bundles/jtreg_bin-5.1.zip/jtreg/lib/testng.jar -XX:MaxRAMPercentage=6 -Djava.io.tmpdir=/opt/mach5/mesos/work_dir/slaves/52628e90-e5e7-4ef3-af97-10d8776d10db-S2289/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/3befb8b8-5446-4dac-8bf7-61c944e0d3cb/runs/5e44fd80-642d-4ad1-8c57-7d0c5635cecb/testoutput/test-support/jtreg_open_test_hotspot_jtreg_vmTestbase_vm_compiler/tmp -XX:+UnlockExperimentalVMOptions -XX:AOTLibrary=/opt/mach5/mesos/work_dir/slaves/52628e90-e5e7-4ef3-af97-10d8776d10db-S2289/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/3befb8b8-5446-4dac-8bf7-61c944e0d3cb/runs/5e44fd80-642d-4ad1-8c57-7d0c5635cecb/./testoutput/test-support/aot/jtreg_open_test_hotspot_jtreg_vmTestbase_vm_compiler/libjava.base.so -server -ea -esa -XX:+TieredCompilation -XX:+PrintTieredEvents -version ]
[2020-09-14T04:29:11.512974297Z] Gathering output for process 8820
[2020-09-14T04:29:11.669440633Z] Waiting for completion for process 8820
[2020-09-14T04:29:11.669737875Z] Waiting for completion finished for process 8820
[2020-09-14T04:29:11.671163078Z] Waiting for completion for process 8820
[2020-09-14T04:29:11.671432678Z] Waiting for completion finished for process 8820
----------System.err:(21/1056)*----------
 stdout: [];
 stderr: [java version "16-ea" 2021-03-16
Java(TM) SE Runtime Environment (fastdebug build 16-ea+16-662)
Java HotSpot(TM) 64-Bit Server VM (fastdebug build 16-ea+16-662, mixed mode, aot, sharing)
]
 exitValue = 0

java.lang.RuntimeException: '^[0-9.]+: \\[compile level=\\d' missing from stdout 

	at jdk.test.lib.process.OutputAnalyzer.stdoutShouldMatch(OutputAnalyzer.java:326)
	at vmTestbase.jit.tiered.Test.main(Test.java:66)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:64)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:564)
	at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:298)
	at java.base/java.lang.Thread.run(Thread.java:832)

JavaTest Message: Test threw exception: java.lang.RuntimeException

The test task description is:

Run test :vmTestbase_vm_compiler with linux-x64-debug with -server -ea -esa #tier6-comp-aot
Comments
The test is removed by JDK-8251462 changes.
28-01-2021
Most of the work spent with "java -version" is to build the module graph. With JDK-8244778, the module graph is built ahead of time (when CDS image is created), so "java -version" now does almost nothing. No bytecodes are executed at all when AOT is enabled (whatever method calls used by "java -version" were compiled by JAOTC): $ jdk-16/fastdebug/bin/java -server -ea -esa -XX:+UnlockDiagnosticVMOptions -XX:+UnlockExperimentalVMOptions -XX:+UseAOTStrictLoading -XX:AOTLibrary=$TOMROOT/libjava.base.so -XX:+TieredCompilation -XX:+PrintTieredEvents -XX:+TraceBytecodes -version java version "16-internal" 2021-03-16 Java(TM) SE Runtime Environment (fastdebug build 16-internal+0-2020-10-27-1416319.thomas.schatzl.jdk-mach5) Java HotSpot(TM) 64-Bit Server VM (fastdebug build 16-internal+0-2020-10-27-1416319.thomas.schatzl.jdk-mach5, mixed mode, aot, sharing) 0 bytecodes executed in 0.2s (0.000MHz) [BytecodeCounter::counter_value = 0] The test should be modified to execute something significant, like a small test program that loops for 5 seconds.
29-10-2020
that explains the absence of 'compile' tiered events (yet it doesn't explain why it started to fail only after JDK-8244778), but there are no call events as well.
17-09-2020
The test is buggy. There's no guarantee that running "java -XX:-TieredCompilation -XX:+PrintTieredEvents -version" will cause JIT compilation. With JDK-8244778, very few Java bytecodes are executed with "java -version". In the failure case, we are using AOT, which further reduces the chance of JIT compilation. The test should be rewritten to execute long enough to ensure JIT compilation.
17-09-2020
[~iklam] - This test failure first shows up in jdk-16+16-662 which is the build-ID when the following fix was integrated: JDK-8244778 Archive full module graph in CDS I think it's possible that this failure is also caused by JDK-8244778.
16-09-2020