JDK-8227647 : [Graal] Test8009761.java fails due to "RuntimeException: static java.lang.Object compiler.uncommontrap.Test8009761.m3(boolean,boolean) not compiled"
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 11,13,15
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • OS: generic
  • CPU: generic
  • Submitted: 2019-07-12
  • Updated: 2024-10-17
  • Resolved: 2020-06-04
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 11 JDK 15
11.0.10-oracleFixed 15 b27Fixed
Related Reports
Duplicate :  
JDK-8233681 - [Graal] compiler/gcbarriers/EqvUncastStepOverBarrier.java test fails with 'java.lang.RuntimeException: Method compilation failed'
Relates :  
JDK-8233681 - [Graal] compiler/gcbarriers/EqvUncastStepOverBarrier.java test fails with 'java.lang.RuntimeException: Method compilation failed'
Description
The following test is failing in the JDK13 CI:

compiler/uncommontrap/Test8009761.java

Here's a snippet of the log file:

#section:main
----------messages:(5/865)----------
command: main -Xbootclasspath/a:. -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -XX:-UseOnStackReplacement -XX:-BackgroundCompilation -Xss512K -XX:+IgnoreUnrecognizedVMOptions -XX:+UnlockExperimentalVMOptions -XX:+EagerJVMCI -XX:CompileCommand=exclude,compiler.uncommontrap.Test8009761::m2 compiler.uncommontrap.Test8009761
reason: User specified action: run main/othervm -Xbootclasspath/a:. -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -XX:-UseOnStackReplacement -XX:-BackgroundCompilation -Xss512K -XX:+IgnoreUnrecognizedVMOptions -XX:+UnlockExperimentalVMOptions -XX:+EagerJVMCI -XX:CompileCommand=exclude,compiler.uncommontrap.Test8009761::m2 compiler.uncommontrap.Test8009761 
Mode: othervm [/othervm specified]
Additional options from @modules: --add-modules java.base --add-exports java.base/jdk.internal.misc=ALL-UNNAMED
elapsed time (seconds): 34.802
----------configuration:(4/111)----------
Boot Layer
  add modules: java.base                   
  add exports: java.base/jdk.internal.misc ALL-UNNAMED

----------System.out:(5/349)----------
CompileCommand: exclude compiler/uncommontrap/Test8009761.m2
WB error: failed to blocking compile at level 4 method  compiler.uncommontrap.Test8009761::m3
WB error: blocking compilation is still in queue!
WB error: failed to blocking compile at level 1 method  compiler.uncommontrap.Test8009761::m3
WB error: blocking compilation is still in queue!
----------System.err:(13/1031)----------
java.lang.RuntimeException: static java.lang.Object compiler.uncommontrap.Test8009761.m3(boolean,boolean) not compiled
	at compiler.uncommontrap.Test8009761.main(Test8009761.java:272)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:567)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.base/java.lang.Thread.run(Thread.java:830)

JavaTest Message: Test threw exception: java.lang.RuntimeException: static java.lang.Object compiler.uncommontrap.Test8009761.m3(boolean,boolean) not compiled
JavaTest Message: shutting down test

STATUS:Failed.`main' threw exception: java.lang.RuntimeException: static java.lang.Object compiler.uncommontrap.Test8009761.m3(boolean,boolean) not compiled
----------rerun:(53/7434)*----------
Comments
Fix request (11u) -- will label after testing completed. I would like to downport this for parity with 11.0.10-oracle. Applies clean.
31-08-2020
URL: https://hg.openjdk.java.net/jdk/jdk/rev/dd71ad3f752b User: kvn Date: 2020-06-04 17:59:57 +0000
04-06-2020
http://cr.openjdk.java.net/~kvn/8227647/webrev.00/
04-06-2020
I am inclining to not unblock Graal compilation if request comes from testing (reason >= Reason_CTW): http://hg.openjdk.java.net/jdk/jdk/file/56d70f6a4543/src/hotspot/share/compiler/compileTask.hpp#l48
03-06-2020
I got LogCompilation output when test failed. It shows that Graal compiled a first method for 12 sec before it takes Test8009761::m3 to compile: <task_queued compile_id='196' method='compiler.uncommontrap.Test8009761 m3 (ZZ)Ljava/lang/Object;' bytes='23' count='1' iicount='1' throwouts='1' blocking='1' stamp='2.665' comment='whitebox' hot_count='1'/> ... <compilation_log thread='40963'> <start_compile_thread name='JVMCI CompilerThread0' thread='40963' process='34219' stamp='0.151'/> <task compile_id='39' method='java.util.concurrent.ConcurrentHashMap get (Ljava/lang/Object;)Ljava/lang/Object;' bytes='162' count='6528' backedge_count='196' iicount='6528' stamp='2.575'> <dependency type='leaf_type' ctxk='jdk/internal/module/ModuleReferenceImpl'/> <dependency type='leaf_type' ctxk='java/util/concurrent/ConcurrentHashMap'/> <task_done success='1' nmsize='2880' count='19387' backedge_count='777' inlined_bytes='904' stamp='14.216'/> </task> <task compile_id='196' method='compiler.uncommontrap.Test8009761 m3 (ZZ)Ljava/lang/Object;' bytes='23' count='1' iicount='1' throwouts='1' blocking='1' stamp='14.216'> Again it shows that first compilation (which is not test's method) can take long time on slow machine.
03-06-2020
I can't reproduce it any more (more powerful Mac machines are used for testing) but -Dgraal.Printcompilation=true output shows that there are several Graal's compilation before Test8009761::m3() begin to compile which could take around 8 sec in this case and I can imaging it can take more then 10 sec in other cases: HotSpotCompilation-39 Ljava/util/concurrent/ConcurrentHashMap; tabAt ([Ljava/util/concurrent/ConcurrentHashMap$Node;I)Ljava/util/concurrent/ConcurrentHashMap$Node; | 4952790us 44B bytecodes 166B codesize HotSpotCompilation-328 Ljdk/internal/reflect/ReflectionFactory; copyMethod (Ljava/lang/reflect/Method;)Ljava/lang/reflect/Method; | 1212184us 346B bytecodes 705B codesize HotSpotCompilation-327 Ljava/lang/reflect/Method; <init> (Ljava/lang/Class;Ljava/lang/String;[Ljava/lang/Class;Ljava/lang/Class;[Ljava/lang/Class;IILjava/lang/String;[B[B[B)V | 1281434us 146B bytecodes 2127B codesize HotSpotCompilation-1989 Ljava/util/BitSet; wordIndex (I)I | 26334us 10B bytecodes 32B codesize HotSpotCompilation-4025 Ljava/util/ArrayList; elementData (I)Ljava/lang/Object; | 68042us 14B bytecodes 167B codesize HotSpotCompilation-1481 Ljava/util/ArrayDeque; elementAt ([Ljava/lang/Object;I)Ljava/lang/Object; | 36523us 8B bytecodes 92B codesize HotSpotCompilation-4148 Ljava/lang/Object; equals (Ljava/lang/Object;)Z | 67729us 22B bytecodes 100B codesize HotSpotCompilation-2518 Lcompiler/uncommontrap/Test8009761; m3 (ZZ)Ljava/lang/Object; | 363731us 228B bytecodes 345B codesize HotSpotCompilation-4321 Ljava/util/ArrayList$Itr; hasNext ()Z | 68859us 40B bytecodes 134B codesize PASSED 49 HotSpotCompilation-329 Ljava/lang/reflect/Method; copy ()Ljava/lang/reflect/Method; | 278674us 168B bytecodes 1030B codesize
03-06-2020
And I can't find what changes in jdk-15+26-1275 could caused it. Note I ran with jdk-15+26-1274 and it passed. The only thing in jdk-15+26-1275 which change Hotspot runtime (I exclude JVTI changes) is JDK-8245707 which increased Metaspace alignment.
03-06-2020
An other note, Graal still continue compilation - task is still on queue. That is why second WB attempts to compile with C1 failed - previous compilation task is still a live: http://hg.openjdk.java.net/jdk/jdk/file/0a32396f7a69/src/hotspot/share/compiler/compileBroker.cpp#l1152
03-06-2020
Failures happens on MacOS (macmini) which are slow. JVMCI drops compilation if after 10 sec (10 checks every 1 sec) compilation is not complete: http://hg.openjdk.java.net/jdk/jdk/file/0a32396f7a69/src/hotspot/share/compiler/compileBroker.cpp#l1583 Here is PrintCompilation output: 13762 281 b 4 compiler.uncommontrap.Test8009761::m3 (23 bytes) wait for blocking compilation timed out Note, Graal starts in Interpreter mode and C1 is start compiling it (more than 3000 compilations) consuming CPU resources. On slow machine with few threads Graal compiler thread will be blocked by C1 compilations.
03-06-2020
It is not related to JDK-8202124 because tiered compilation is enabled. I will look what changes caused it. The test does blocking compilation but for some reason it returned from compilation request with request still in queue.
03-06-2020
[~kvn] - This test has failed in almost every Tier3 since jdk-15+26-1275 (4 recent sightings so far). Any idea what has changed recently that would increase the frequency of this test failing? Should this test be ProblemListed?
03-06-2020