JDK-8211094 : [Graal] jdk/jfr/event/compiler/TestCompilerCompile.java fails: java.lang.RuntimeException: Value not atLeast0, field='inlinedBytes', value='-102': expected -102 >= 0
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 11,12,13
  • Priority: P4
  • Status: Closed
  • Resolution: Duplicate
  • Submitted: 2018-09-25
  • Updated: 2020-04-08
  • Resolved: 2020-04-08
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 13 JDK 14
13Resolved 14Resolved
Related Reports
Duplicate :  
JDK-8225497 - Update Graal
Relates :  
JDK-8193210 - [JVMCI/Graal] add JFR compiler phase/inlining events
Description
This fails pretty regularly in Twitter nightly testing with Graal:

Error: Value not atLeast0, field='inlinedBytes', value='-102': expected -102 >= 0
Failed event:
Compilation {
  startTime = 5042961063
  duration = 19889808
  eventThread = {
    osName = "JVMCI CompilerThread7"
    osThreadId = 378225
    javaName = "JVMCI CompilerThread7"
    javaThreadId = 13
    group = {
      parent = null
      name = "system"
    }
  }
  method = {
    type = {
      classLoader = {
        type = null
        name = "bootstrap"
      }
      name = "java/lang/Long"
      package = {
        name = "java/lang"
        module = {
          name = "java.base"
          version = "11.0.0.0.1-internal"
          location = "jrt:/java.base"
          classLoader = {
            type = null
            name = "bootstrap"
          }
        }
        exported = true
      }
      modifiers = 49
    }
    name = "numberOfTrailingZeros"
    descriptor = "(J)I"
    modifiers = 9
    hidden = false
  }
  compileId = 5534
  compileLevel = 4
  succeded = true
  isOsr = false
  codeSize = 104
  inlinedBytes = -102
}

STDERR:
OpenJDK 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release.
OpenJDK 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release.
java.lang.RuntimeException: Value not atLeast0, field='inlinedBytes', value='-102': expected -102 >= 0
	at jdk.test.lib.Asserts.fail(Asserts.java:594)
	at jdk.test.lib.Asserts.assertGreaterThanOrEqual(Asserts.java:288)
	at jdk.test.lib.jfr.EventField.lambda$atLeast$4(EventField.java:76)
	at jdk.test.lib.jfr.EventField.doAssert(EventField.java:116)
	at jdk.test.lib.jfr.EventField.atLeast(EventField.java:76)
	at jdk.jfr.event.compiler.TestCompilerCompile.verifyEvent(TestCompilerCompile.java:139)
	at jdk.jfr.event.compiler.TestCompilerCompile.doTest(TestCompilerCompile.java:98)
	at jdk.jfr.event.compiler.TestCompilerCompile.main(TestCompilerCompile.java:62)
	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:566)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:115)
	at java.base/java.lang.Thread.run(Thread.java:834)
Comments
This was fixed in JDK 13 by JDK-8223346 and JDK 14 by JDK-8225497.
07-04-2020
I never saw the failure in the way you did, but part of the fix was adding an assert which caught the problem during CTW. So it was certainly occurring but nothing was complaining about the bad value before.
01-07-2019
Did this test ever fail during testing at Oracle?
01-07-2019
This should be resolved by https://github.com/oracle/graal/commit/1f113b42bd44a05c8a91b0d919f12793ba772553
08-05-2019
No it didn't make it into the last Graal update. We can defer it for the next update.
12-12-2018
Hi [~never], Can you please confirm if this bug fixed now with the recent JDK-8214023 Graal Update and if can be closed now? OR should we defer this? Thanks.
11-12-2018
A root compile of a MethodSubstitution is just a substititon. Nothing else is visibly inlined. You can figure it out from looking at the getMethods(), but as I said the first method in getMethods should be the real root method and that's what should be subtracted from getBytecodeSize. Though thinking about it again, I suspect Graal should be populating the CompilationResult differently for this case. I don't think the ResolvedJavaMethod of a MethodSubstitution should really show up in the methods of the result at all. Let me see if I can come up with a fix.
27-09-2018
Is there an easy way to figure out if the compiled code is actually from a MethodSubstitution? Or where would we return 0?
27-09-2018
Good question. Are there MethodSubstitutions that actually inline other Java methods or is that not allowed? Anyway, I think the only reasonable thing to return for inlined bytecodes is 0.
26-09-2018
I think the problem is that the expression result.getBytecodeSize() - method.getCodeSize() assumes that the bytes in method were actually compiled into this graph which isn't the case for a MethodSubstitution. If you add a check that the above expression always returns a non-negative value you can see failures when running a CTW. I think the expression should really be result.getBytecodeSize() - result.getMethods()[0].getCodeSize() since that really represents the root method which was compiled into the graph. It might be best to wrap that up as a method in CompilationResult. Though actually it's a bit unclear what values should be returned for a MethodSubstitution in the first place. Maybe always 0 for inlined bytecodes?
26-09-2018
Actually no: HotSpotMethod<Long.numberOfTrailingZeros(long)>: getBytecodeSize=232, getCodeSize, 116
25-09-2018
Thanks for the pointer. I found where the information is passed down in to the VM and that's probably the root of the issue: http://hg.openjdk.java.net/jdk/jdk11/file/1ddf9a99e4ad/src/jdk.internal.vm.compiler/share/classes/org.graalvm.compiler.hotspot/src/org/graalvm/compiler/hotspot/CompilationTask.java#l198
25-09-2018
FTR, we have JDK-8193210 to keep track of JVMCI not supporting JFR events but it seems that this failure is not related to JFR. ILW = Number of inlined bytecodes is wrong, diagnostic events with JVMCI compilations, no workaround = MLH = P4
25-09-2018
The only place where we set inlined bytes is here: http://hg.openjdk.java.net/jdk/jdk11/file/1ddf9a99e4ad/src/hotspot/share/compiler/compileBroker.cpp#l1949 and for JVMCI compilations ci_env is NULL.
25-09-2018
Currently there is no JFR implementation of the EventProvider so the inlinedBytes number is coming from the CompilerBroker. Are we even passing inlined bytes down into the VM? The only thing that jumps out is that Long.numberOfTrailingZeros has a MethodSubstitution.
25-09-2018
[~never] is it possible that this is related to the method having a MethodSubstitution?
25-09-2018
I cannot reproduce with an isolated test case but it's interesting: 2667 467 4 java.lang.Long::numberOfTrailingZeros (116 bytes) id=467 ci_env=0x0 num_inlined_bytecodes=116 Since the inlined bytes number is the same as the bytecode size does this tells us that method.getCodeSize() is zero? return HotSpotCompilationRequestResult.success(result.getBytecodeSize() - method.getCodeSize());
25-09-2018