jfr TestCompilerPhase test fails on win-32

[karianna]

https://trss.adoptium.net/output/test?id=616f7c69c6182d021789fb99

[2021-10-20T01:08:59.665Z] rerun: [2021-10-20T01:08:59.665Z] cd 'E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\TKG\output_16346911874799\jdk_jfr_2\work\scratch\2' && \ [2021-10-20T01:08:59.665Z] PATH='C:\Program Files\Temurin\jdk-8.0.302.8-hotspot\bin;C:\cygwin64\bin;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0;C:\Program Files (x86)\Microsoft SQL Server\100\Tools\Binn;C:\Program Files\Microsoft SQL Server\100\Tools\Binn;C:\Program Files\Microsoft SQL Server\100\DTS\Binn;C:\Strawberry\perl\bin;C:\Program Files\Git\cmd;C:\openjdk\jdk-8\bin;C:\apache-ant\apache-ant-1.10.5\bin;C:\Program Files\Microsoft SQL Server\110\Tools\Binn;C:\Program Files (x86)\Microsoft SDKs\TypeScript\1.0;C:\Program Files\Microsoft SQL Server\120\Tools\Binn;C:\Program Files (x86)\IncrediBuild;C:\rust\bin;C:\Program Files\IcedTeaWEB\bin' \ [2021-10-20T01:08:59.665Z] SystemDrive=C: \ [2021-10-20T01:08:59.665Z] SystemRoot='C:\Windows' \ [2021-10-20T01:08:59.665Z] TEMP='C:\Users\JENKIN~1.TST\AppData\Local\Temp' \ [2021-10-20T01:08:59.665Z] TMP='E:\jenkinstmp' \ [2021-10-20T01:08:59.665Z] windir='C:\Windows' \ [2021-10-20T01:08:59.665Z] 'E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\openjdkbinary\j2sdk-image\bin\javac' \ [2021-10-20T01:08:59.665Z] -J-ea \ [2021-10-20T01:08:59.665Z] -J-esa \ [2021-10-20T01:08:59.665Z] -J-Xmx512m \ [2021-10-20T01:08:59.665Z] -J-Djava.awt.headless=true \ [2021-10-20T01:08:59.665Z] -J-Dtest.vm.opts='-ea -esa -Xmx512m -Djava.awt.headless=true' \ [2021-10-20T01:08:59.665Z] -J-Dtest.tool.vm.opts='-J-ea -J-esa -J-Xmx512m -J-Djava.awt.headless=true' \ [2021-10-20T01:08:59.665Z] -J-Dtest.compiler.opts= \ [2021-10-20T01:08:59.665Z] -J-Dtest.java.opts= \ [2021-10-20T01:08:59.665Z] -J-Dtest.jdk='E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\openjdkbinary\j2sdk-image' \ [2021-10-20T01:08:59.665Z] -J-Dcompile.jdk='E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\openjdkbinary\j2sdk-image' \ [2021-10-20T01:08:59.665Z] -J-Dtest.timeout.factor=8.0 \ [2021-10-20T01:08:59.665Z] -J-Dtest.root='E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\openjdk\openjdk-jdk\jdk\test' \ [2021-10-20T01:08:59.665Z] -J-Dtest.name=jdk/jfr/event/compiler/TestCompilerPhase.java \ [2021-10-20T01:08:59.665Z] -J-Dtest.file='E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\openjdk\openjdk-jdk\jdk\test\jdk\jfr\event\compiler\TestCompilerPhase.java' \ [2021-10-20T01:08:59.665Z] -J-Dtest.src='E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\openjdk\openjdk-jdk\jdk\test\jdk\jfr\event\compiler' \ [2021-10-20T01:08:59.666Z] -J-Dtest.src.path='E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\openjdk\openjdk-jdk\jdk\test\jdk\jfr\event\compiler;E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\openjdk\openjdk-jdk\jdk\test\lib;E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\openjdk\openjdk-jdk\jdk\test' \ [2021-10-20T01:08:59.666Z] -J-Dtest.classes='E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\TKG\output_16346911874799\jdk_jfr_2\work\classes\3\jdk\jfr\event\compiler' \ [2021-10-20T01:08:59.666Z] -J-Dtest.class.path='E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\TKG\output_16346911874799\jdk_jfr_2\work\classes\3\jdk\jfr\event\compiler;E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\TKG\output_16346911874799\jdk_jfr_2\work\classes\3\lib;E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\TKG\output_16346911874799\jdk_jfr_2\work\classes\3' \ [2021-10-20T01:08:59.666Z] -J-Dtest.class.path.prefix='E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\TKG\output_16346911874799\jdk_jfr_2\work\classes\3\jdk\jfr\event\compiler;E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\openjdk\openjdk-jdk\jdk\test\jdk\jfr\event\compiler;E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\TKG\output_16346911874799\jdk_jfr_2\work\classes\3\lib;E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\TKG\output_16346911874799\jdk_jfr_2\work\classes\3' \ [2021-10-20T01:08:59.666Z] -d 'E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\TKG\output_16346911874799\jdk_jfr_2\work\classes\3\jdk\jfr\event\compiler' \ [2021-10-20T01:08:59.666Z] -sourcepath 'E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\openjdk\openjdk-jdk\jdk\test\jdk\jfr\event\compiler;E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\openjdk\openjdk-jdk\jdk\test\lib;E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\openjdk\openjdk-jdk\jdk\test' \ [2021-10-20T01:08:59.666Z] -classpath 'E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\openjdk\openjdk-jdk\jdk\test\jdk\jfr\event\compiler;E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\TKG\output_16346911874799\jdk_jfr_2\work\classes\3\jdk\jfr\event\compiler;E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\TKG\output_16346911874799\jdk_jfr_2\work\classes\3\lib;E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\TKG\output_16346911874799\jdk_jfr_2\work\classes\3;E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\openjdkbinary\j2sdk-image\lib\tools.jar' \ [2021-10-20T01:08:59.666Z] -XDignore.symbol.file=true 'E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\openjdk\openjdk-jdk\jdk\test\jdk\jfr\event\compiler\TestCompilerPhase.java' [2021-10-20T01:08:59.666Z] direct: [2021-10-20T01:08:59.666Z] Note: E:\workspace\Test_openjdk8_hs_extended.openjdk_x86-32_windows_testList_2\aqa-tests\openjdk\openjdk-jdk\jdk\test\lib\jdk\test\lib\Utils.java uses unchecked or unsafe operations. [2021-10-20T01:08:59.666Z] Note: Recompile with -Xlint:unchecked for details. [2021-10-20T01:08:59.666Z] [2021-10-20T01:08:59.666Z] ACTION: main -- Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: No events: expected false, was true [2021-10-20T01:08:59.666Z] REASON: User specified action: run main/othervm -Xbootclasspath/a:. -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -XX:CompileOnly=jdk.jfr.event.compiler.TestCompilerPhase::dummyMethod -Xbootclasspath/a:. jdk.jfr.event.compiler.TestCompilerPhase [2021-10-20T01:08:59.666Z] TIME: 1.296 seconds [2021-10-20T01:08:59.666Z] messages: [2021-10-20T01:08:59.666Z] command: main -Xbootclasspath/a:. -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -XX:CompileOnly=jdk.jfr.event.compiler.TestCompilerPhase::dummyMethod -Xbootclasspath/a:. jdk.jfr.event.compiler.TestCompilerPhase [2021-10-20T01:08:59.666Z] reason: User specified action: run main/othervm -Xbootclasspath/a:. -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -XX:CompileOnly=jdk.jfr.event.compiler.TestCompilerPhase::dummyMethod -Xbootclasspath/a:. jdk.jfr.event.compiler.TestCompilerPhase [2021-10-20T01:08:59.666Z] Mode: othervm [/othervm specified] [2021-10-20T01:08:59.666Z] elapsed time (seconds): 1.296 [2021-10-20T01:08:59.666Z] configuration: [2021-10-20T01:08:59.666Z] STDOUT: [2021-10-20T01:08:59.666Z] Warning: 'NoSuchMethodError' on register of sun.hotspot.WhiteBox::NMTNewArena(J)J [2021-10-20T01:08:59.666Z] Warning: 'NoSuchMethodError' on register of sun.hotspot.WhiteBox::NMTFreeArena(J)V [2021-10-20T01:08:59.666Z] Warning: 'NoSuchMethodError' on register of sun.hotspot.WhiteBox::NMTArenaMalloc(JJ)V [2021-10-20T01:08:59.666Z] WB error: invalid compilation level 4 [2021-10-20T01:08:59.666Z] hello! [2021-10-20T01:08:59.666Z] STDERR: [2021-10-20T01:08:59.666Z] java.lang.RuntimeException: No events: expected false, was true [2021-10-20T01:08:59.666Z] at jdk.test.lib.Asserts.fail(Asserts.java:594) [2021-10-20T01:08:59.666Z] at jdk.test.lib.Asserts.assertFalse(Asserts.java:461) [2021-10-20T01:08:59.666Z] at jdk.test.lib.jfr.Events.hasEvents(Events.java:159) [2021-10-20T01:08:59.666Z] at jdk.jfr.event.compiler.TestCompilerPhase.main(TestCompilerPhase.java:76) [2021-10-20T01:08:59.666Z] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [2021-10-20T01:08:59.666Z] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) [2021-10-20T01:08:59.666Z] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [2021-10-20T01:08:59.666Z] at java.lang.reflect.Method.invoke(Method.java:498) [2021-10-20T01:08:59.666Z] at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127) [2021-10-20T01:08:59.666Z] at java.lang.Thread.run(Thread.java:748) [2021-10-20T01:08:59.666Z] [2021-10-20T01:08:59.666Z] JavaTest Message: Test threw exception: java.lang.RuntimeException: No events: expected false, was true [2021-10-20T01:08:59.666Z] JavaTest Message: shutting down test

[sophia-guo]

same on jdk17

[roberttoyonaga]

It seems that the reason that this test fails on 32 bit windows is that Hotspot may only use the C1 compiler in this configuration.

The CompilerPhase JFR events are only emitted from C2 code. So although the test succeeds in compiling the method it intends to (with C1), it isn't able to generate the JFR events it expects.

In the JDK 17 code, if the system is Windows and not 64 bit, NeverActAsServerClassMachine will be set. This results in setting the compilation mode to be quick_only, which results in constraining to C1 compilation. The code flow in JDK 8 is slightly different, but it's still the case that client mode prevents C2 and CompilerPhase events.

Additionally, the stacktrace in your description mentions:

[2021-10-20T01:08:59.666Z] WB error: invalid compilation level 4

This means that C2 won't be used (level4) and will default to level 1.

Similarly, when I run a Grinder job I can reproduce this failure because for whatever reason the job defaults to a "client VM" (no C2). https://ci.adoptium.net/view/Test_grinder/job/Grinder/8833/console Resulting in the same failure due to no events.

Overall, it seems that the problem is not the JFR code itself, but instead that the test can only work when in Server VM mode using C2.

[roberttoyonaga]

@sophia-guo What is the recommended course of action?

Should we update https://github.com/adoptium/aqa-tests/blob/master/openjdk/excludes/ProblemList_openjdk8.txt#L419 to only exclude windows 32bit (and arm linux 32 bit). Right now this test is excluded for all platforms, but I think it works fine for x86_64 linux, arm linux 64, and windows 64.

[roberttoyonaga]

The test succeeds if I specify: -XX:-NeverActAsServerClassMachine. This prevents it from defaulting to C1 only. I'll try to get this change in upstream.

[roberttoyonaga]

Opened PR to jdk17u-dev https://github.com/openjdk/jdk17u-dev/pull/2222 JBS issue: https://bugs.openjdk.org/browse/JDK-8326521

[smlambert]

Thanks for all of the good investigation and work that you are doing @roberttoyonaga !