JDK-8199624 : [Graal] Blocking jvmci compilations time out
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 11
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2018-03-14
  • Updated: 2018-04-11
  • Resolved: 2018-03-21
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
11 b07Fixed
Related Reports
Relates :  
Relates :  
Description
compiler/calls intermittently fail when running with Graal as JIT.
All failures pretty much the same and look like "Unexpected caller compilation level: expected 4 to equal 0".

I did modify CallsBase:compileMethod by adding check wb.isMethodCompiled(method)

    protected final void compileMethod(Method method, int compLevel) {
        wb.deoptimizeMethod(method);
        Asserts.assertTrue(wb.isMethodCompilable(method, compLevel));
        wb.enqueueMethodForCompilation(method, compLevel);

        boolean waited = false;
        long startTime = System.currentTimeMillis();
        while (! wb.isMethodCompiled(method)) {
            try { Thread.sleep(10); } catch (Exception e) {}
            waited = true;
        }
        if (waited)
            System.out.println("Waited for method being compiled " + (System.currentTimeMillis() - startTime) + " ms");
    }

and I see that from run to run we can wait up to 100 ms for method being compiled.

I also verified that wb.enqueueMethodForCompilation returns true.
So it looks like the Graal compilation is not blocking although we run with -Xbatch.

Comments
Sounds reasonable to me.
20-03-2018

I think we want to avoid checking the PrintCompilation output for all tests that trigger a compilation because that would mean that we need to spawn a separate VM process and verify the output. Instead, I suggest to increase the timeout value for blocking jvmci compilations and change the WhiteBox API to return false in case a blocking compilation issued through enqueueMethodForCompilation does not block (i.e. times out). We can then catch and ignore the timeout in the affected tests: http://cr.openjdk.java.net/~thartmann/8199624/webrev.00/ I've verified that the timeout value is high enough in most cases (100 runs) and that the tests still pass in case the jvmci compilation does still time out. More tests might be affected but I think we should only fix them on demand.
20-03-2018

Doubling JVMCI_COMPILATION_PROGRESS_WAIT_TIMESLICE is fine as this mechanism is specific to -Xbatch and only exists to mitigate timeouts. However, you should probably also add -XX:+PrintCompilation and check for the expected output as you will never be guaranteed to have any given compilation succeed before timing out.
19-03-2018

Your job reached the jtreg maxOutputSize (see "Output overflow") and therefore didn't log the "wait for blocking compilation timed out" message. I've executed some runs with a build that has the printing always enabled and I can see the warning whenever the test fails: jib > 4519 685 b 4 compiler.calls.common.InvokeVirtual::callee (18 bytes) wait for blocking compilation timed out jib > STDERR: jib > java.lang.RuntimeException: Unexpected callee compilation level: expected 4 to equal 0 jib > at jdk.test.lib.Asserts.fail(Asserts.java:594) jib > at jdk.test.lib.Asserts.assertEquals(Asserts.java:205) jib > at jdk.test.lib.Asserts.assertEQ(Asserts.java:178) jib > at compiler.calls.common.CallsBase.runTest(CallsBase.java:159) jib > at compiler.calls.common.InvokeVirtual.main(InvokeVirtual.java:36) jib > at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) jib > at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) jib > at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) jib > at java.base/java.lang.reflect.Method.invoke(Method.java:564) jib > at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:115) jib > at java.base/java.lang.Thread.run(Thread.java:842) I've doubled JVMCI_COMPILATION_PROGRESS_WAIT_TIMESLICE but still see failures (although much more intermittent). I think we can either: - Fix the tests to add -XX:+PrintCompilation and check for the "wait for blocking compilation timed out" warning in the output or - Increase the wait time even further to avoid time outs (but this won't work if there is a real race condition due to the application acquiring the same locks that the JVMCI compiler uses) What do you think?
19-03-2018

Similar issues in runtime/exceptionMsgs/IncompatibleClassChangeError/IncompatibleClassChangeErrorTest.java runtime/exceptionMsgs/AbstractMethodError/AbstractMethodErrorTest.java
15-03-2018

No, I don't see "wait for blocking compilation timed out" when running with -XX:+PrintCompilation. Please see CompiledInvokeVirtual2CompiledTest.jtr.PrintComp attached
15-03-2018

Thanks Doug, in this case we should see "wait for blocking compilation timed out" with -XX:+PrintCompilation. Katya, could you check if that's the case?
15-03-2018

It could be related to JDK-8146705.
15-03-2018

Doug, any idea why Graal does not seem to respect -Xbatch in these cases?
15-03-2018

ILW = test failures due to Graal compilation not blocking with -Xbatch; only with Graal as JIT, intermittent; disable Graal! = MLM = P4
15-03-2018

Running with -XX:+EagerJVMCI doesn't help as well.
14-03-2018

List of failed tests: compiler/aot/calls/fromAot/AotInvokeDynamic2CompiledTest.java compiler/aot/calls/fromAot/AotInvokeInterface2CompiledTest.java compiler/aot/calls/fromAot/AotInvokeSpecial2CompiledTest.java compiler/aot/calls/fromAot/AotInvokeStatic2CompiledTest.java compiler/aot/calls/fromAot/AotInvokeVirtual2CompiledTest.java compiler/aot/calls/fromCompiled/CompiledInvokeDynamic2AotTest.java compiler/aot/calls/fromCompiled/CompiledInvokeInterface2AotTest.java compiler/aot/calls/fromCompiled/CompiledInvokeSpecial2AotTest.java compiler/aot/calls/fromCompiled/CompiledInvokeStatic2AotTest.java compiler/aot/calls/fromCompiled/CompiledInvokeVirtual2AotTest.java compiler/calls/fromCompiled/CompiledInvokeDynamic2CompiledTest.java compiler/calls/fromCompiled/CompiledInvokeDynamic2NativeTest.java compiler/calls/fromCompiled/CompiledInvokeInterface2CompiledTest.java compiler/calls/fromCompiled/CompiledInvokeInterface2InterpretedTest.java compiler/calls/fromCompiled/CompiledInvokeInterface2NativeTest.java compiler/calls/fromCompiled/CompiledInvokeSpecial2CompiledTest.java compiler/calls/fromCompiled/CompiledInvokeSpecial2InterpretedTest.java compiler/calls/fromCompiled/CompiledInvokeSpecial2NativeTest.java compiler/calls/fromCompiled/CompiledInvokeStatic2CompiledTest.java compiler/calls/fromCompiled/CompiledInvokeStatic2InterpretedTest.java compiler/calls/fromCompiled/CompiledInvokeStatic2NativeTest.java compiler/calls/fromCompiled/CompiledInvokeVirtual2CompiledTest.java compiler/calls/fromCompiled/CompiledInvokeVirtual2InterpretedTest.java compiler/calls/fromCompiled/CompiledInvokeVirtual2NativeTest.java compiler/calls/fromInterpreted/InterpretedInvokeDynamic2CompiledTest.java compiler/calls/fromInterpreted/InterpretedInvokeSpecial2CompiledTest.java compiler/calls/fromInterpreted/InterpretedInvokeVirtual2CompiledTest.java compiler/calls/fromNative/NativeInvokeStatic2CompiledTest.java compiler/cpuflags/TestAESIntrinsicsOnUnsupportedConfig.java
14-03-2018

To run for example compiler/calls/fromCompiled/CompiledInvokeVirtual2CompiledTest.java do > jtreg -va -k:!ignore -jdk:JDK.HS_fastdebug -vmoptions:--XX:+UnlockExperimentalVMOptions -XX:+EnableJVMCI -XX:+TieredCompilation -XX:+UseJVMCICompiler -Djvmci.Compiler=graal compiler/calls/fromCompiled/CompiledInvokeVirtual2CompiledTest.java
14-03-2018