JDK-8265295 : vmTestbase/vm/mlvm/mixed/stress/regression/b6969574/INDIFY_Test.java failed with "MH.invokeExact() invocation time order (173.3 ns) is greater than of invokedynamic instruction(15.5 ns)!"
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 17,18,19,20,22
  • Priority: P4
  • Status: Open
  • Resolution: Unresolved
  • OS: windows
  • CPU: x86_64
  • Submitted: 2021-04-15
  • Updated: 2023-09-24
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.
Other
tbdUnresolved
Related Reports
Relates :  
JDK-8217800 - MH.invokeWithArguments(), exact types invocation time > MH.invokeExact()
Relates :  
JDK-8218178 - vmTestbase/vm/mlvm/mixed/stress/regression/b6969574/INDIFY_Test.java fails with -Xcomp
Sub Tasks
JDK-8265463 :  
ProblemList vmTestbase/vm/mlvm/mixed/stress/regression/b6969574/INDIFY_Test.java on Win-X64 -Xcomp - Resolved
JDK-8269316 :  
ProblemList vmTestbase/vm/mlvm/mixed/stress/regression/b6969574/INDIFY_Test.java on Linux-X64 -Xcomp - Resolved
Description
The following test failed in the JDK17 CI:

vmTestbase/vm/mlvm/mixed/stress/regression/b6969574/INDIFY_Test.java

Here's a snippet from the log file:

======== Conclusions
### TRACE 1: Comparing invocation time orders
### TRACE 1: invokedynamic instruction <= Reflection API Method.invoke(): Good.
### TRACE 1: MH.invokeExact() <= Direct call: Good.
### TRACE 1: MH.invoke() <= Direct call: Good.
#>  
#>  WARNING: switching log to verbose mode,
#>      because error is complained
#>  
# ERROR: Test marked failed at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.verifyTimeOrder(INDIFY_Test.java:296):
# ERROR: MH.invokeExact() invocation time order (173.3 ns) is greater than of invokedynamic instruction(15.5 ns)!
The following stacktrace is for failure analysis.
nsk.share.TestFailure: Test marked failed at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.verifyTimeOrder(INDIFY_Test.java:296): MH.invokeExact() invocation time order (173.3 ns) is greater than of invokedynamic instruction(15.5 ns)!
	at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:432)
	at nsk.share.Log.complain(Log.java:403)
	at nsk.share.Log.complain(Log.java:416)
	at vm.mlvm.share.Env.complain(Env.java:172)
	at vm.mlvm.share.MlvmTest.markTestFailedImpl(MlvmTest.java:265)
	at vm.mlvm.share.MlvmTest.markTestFailed(MlvmTest.java:247)
	at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.verifyTimeOrder(INDIFY_Test.java:296)
	at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.run(INDIFY_Test.java:402)
	at vm.mlvm.share.MlvmTestExecutor.runMlvmTestInstance(MlvmTestExecutor.java:382)
	at vm.mlvm.share.MlvmTestExecutor.runMlvmTest(MlvmTestExecutor.java:327)
	at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:244)
	at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:186)
	at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:157)
	at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:325)
	at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.main(INDIFY_Test.java:424)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.base/java.lang.Thread.run(Thread.java:831)
### TRACE 1: MH.invokeExact() <= invokedynamic instruction: Good.
# ERROR: Failed runs: 1 of 1
The following stacktrace is for failure analysis.
nsk.share.TestFailure: Failed runs: 1 of 1
	at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:432)
	at nsk.share.Log.complain(Log.java:403)
	at vm.mlvm.share.Env.complain(Env.java:164)
	at vm.mlvm.share.MlvmTestExecutor.runMlvmTestInstance(MlvmTestExecutor.java:408)
	at vm.mlvm.share.MlvmTestExecutor.runMlvmTest(MlvmTestExecutor.java:327)
	at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:244)
	at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:186)
	at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:157)
	at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:325)
	at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.main(INDIFY_Test.java:424)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.base/java.lang.Thread.run(Thread.java:831)
### TRACE 1: TEST FAILED


#>  
#>  SUMMARY: Following errors occured
#>      during test execution:
#>  
# ERROR: Test marked failed at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.verifyTimeOrder(INDIFY_Test.java:296):
# ERROR: MH.invokeExact() invocation time order (173.3 ns) is greater than of invokedynamic instruction(15.5 ns)!
# ERROR: Failed runs: 1 of 1
----------System.err:(0/0)----------
----------rerun:(49/6918)*----------

The failure mode looks very similar to a much older bug:

    JDK-8217800 MH.invokeWithArguments(), exact types invocation time > MH.invokeExact()
Comments
Here's a log file snippet from the jdk-22+17-1272-tier8 sighting: vmTestbase/vm/mlvm/mixed/stress/regression/b6969574/INDIFY_Test.java #section:main ----------messages:(6/317)---------- command: main vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test reason: User specified action: run main/othervm vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test started: Sun Sep 24 01:57:51 UTC 2023 Mode: othervm [/othervm specified] finished: Sun Sep 24 01:57:53 UTC 2023 elapsed time (seconds): 2.343 ----------configuration:(0/0)---------- ----------System.out:(118/9524)---------- ### TRACE 1: Direct call: 16.0 ns ### TRACE 1: Reflection API Method.invoke(): 32.0 ns ### TRACE 1: MH.invokeExact(): 31.0 ns // 1.0 times FASTER than Reflection API Method.invoke() ### TRACE 1: MH.invoke(): 31.0 ns // 1.0 times FASTER than Reflection API Method.invoke() ### TRACE 1: invokedynamic instruction: 0.0 ns // Infinity times FASTER than Reflection API Method.invoke() ### TRACE 1: Direct call: 0.0 ns ### TRACE 1: Reflection API Method.invoke(): 31.0 ns ### TRACE 1: MH.invokeExact(): 16.0 ns // 1.9 times FASTER than Reflection API Method.invoke() ### TRACE 1: MH.invoke(): 31.0 ns // 1.0 times slower than Reflection API Method.invoke() ### TRACE 1: invokedynamic instruction: 0.0 ns // Infinity times FASTER than Reflection API Method.invoke() ### TRACE 1: Direct call: 0.0 ns ### TRACE 1: Reflection API Method.invoke(): 32.0 ns ### TRACE 1: MH.invokeExact(): 15.0 ns // 2.1 times FASTER than Reflection API Method.invoke() ### TRACE 1: MH.invoke(): 32.0 ns // 1.0 times slower than Reflection API Method.invoke() ### TRACE 1: invokedynamic instruction: 0.0 ns // Infinity times FASTER than Reflection API Method.invoke() ### TRACE 1: Direct call: 0.0 ns ### TRACE 1: Reflection API Method.invoke(): 31.0 ns ### TRACE 1: MH.invokeExact(): 16.0 ns // 1.9 times FASTER than Reflection API Method.invoke() ### TRACE 1: MH.invoke(): 31.0 ns // 1.0 times slower than Reflection API Method.invoke() ### TRACE 1: invokedynamic instruction: 16.0 ns // 1.9 times FASTER than Reflection API Method.invoke() ### TRACE 1: Direct call: 0.0 ns ### TRACE 1: Reflection API Method.invoke(): 31.0 ns ### TRACE 1: MH.invokeExact(): 16.0 ns // 1.9 times FASTER than Reflection API Method.invoke() ### TRACE 1: MH.invoke(): 31.0 ns // 1.0 times slower than Reflection API Method.invoke() ### TRACE 1: invokedynamic instruction: 16.0 ns // 1.9 times FASTER than Reflection API Method.invoke() ### TRACE 1: Direct call: 0.0 ns ### TRACE 1: Reflection API Method.invoke(): 31.0 ns ### TRACE 1: MH.invokeExact(): 16.0 ns // 1.9 times FASTER than Reflection API Method.invoke() ### TRACE 1: MH.invoke(): 31.0 ns // 1.0 times slower than Reflection API Method.invoke() ### TRACE 1: invokedynamic instruction: 15.0 ns // 2.1 times FASTER than Reflection API Method.invoke() ### TRACE 1: Direct call: 0.0 ns ### TRACE 1: Reflection API Method.invoke(): 32.0 ns ### TRACE 1: MH.invokeExact(): 15.0 ns // 2.1 times FASTER than Reflection API Method.invoke() ### TRACE 1: MH.invoke(): 32.0 ns // 1.0 times slower than Reflection API Method.invoke() ### TRACE 1: invokedynamic instruction: 15.0 ns // 2.1 times FASTER than Reflection API Method.invoke() ### TRACE 1: Direct call: 0.0 ns ### TRACE 1: Reflection API Method.invoke(): 31.0 ns ### TRACE 1: MH.invokeExact(): 16.0 ns // 1.9 times FASTER than Reflection API Method.invoke() ### TRACE 1: MH.invoke(): 31.0 ns // 1.0 times slower than Reflection API Method.invoke() ### TRACE 1: invokedynamic instruction: 16.0 ns // 1.9 times FASTER than Reflection API Method.invoke() ### TRACE 1: Direct call: 0.0 ns ### TRACE 1: Reflection API Method.invoke(): 31.0 ns ### TRACE 1: MH.invokeExact(): 16.0 ns // 1.9 times FASTER than Reflection API Method.invoke() ### TRACE 1: MH.invoke(): 31.0 ns // 1.0 times slower than Reflection API Method.invoke() ### TRACE 1: invokedynamic instruction: 16.0 ns // 1.9 times FASTER than Reflection API Method.invoke() ### TRACE 1: Direct call: 0.0 ns ### TRACE 1: Reflection API Method.invoke(): 31.0 ns ### TRACE 1: MH.invokeExact(): 16.0 ns // 1.9 times FASTER than Reflection API Method.invoke() ### TRACE 1: MH.invoke(): 31.0 ns // 1.0 times slower than Reflection API Method.invoke() ### TRACE 1: invokedynamic instruction: 15.0 ns // 2.1 times FASTER than Reflection API Method.invoke() ### TRACE 1: ======== Results (absolute); warmups: 5; measurements: 10; iterations/run: 1000000; micro iterations: 5 ### TRACE 1: Direct call: 1.6 ns (stddev: 4.8 = 299%) // 19.6 times FASTER than Reflection API Method.invoke() ### TRACE 1: Reflection API Method.invoke(): 31.3 ns (stddev: 0.5 = 1%) ### TRACE 1: MH.invokeExact(): 17.3 ns (stddev: 4.6 = 26%) // 1.8 times FASTER than Reflection API Method.invoke() ### TRACE 1: MH.invoke(): 31.2 ns (stddev: 0.4 = 1%) // 1.0 times FASTER than Reflection API Method.invoke() ### TRACE 1: invokedynamic instruction: 10.9 ns (stddev: 7.1 = 65%) // 2.9 times FASTER than Reflection API Method.invoke() ### TRACE 1: ======== Conclusions ### TRACE 1: Comparing invocation time orders ### TRACE 1: invokedynamic instruction <= Reflection API Method.invoke(): Good. ### TRACE 1: MH.invokeExact() <= Direct call: Good. #> #> WARNING: switching log to verbose mode, #> because error is complained #> # ERROR: Test marked failed at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.verifyTimeOrder(INDIFY_Test.java:296): # ERROR: MH.invoke() invocation time order (31.2 ns) is greater than of Direct call(1.6 ns)! The following stacktrace is for failure analysis. nsk.share.TestFailure: Test marked failed at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.verifyTimeOrder(INDIFY_Test.java:296): MH.invoke() invocation time order (31.2 ns) is greater than of Direct call(1.6 ns)! at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:431) at nsk.share.Log.complain(Log.java:402) at nsk.share.Log.complain(Log.java:415) at vm.mlvm.share.Env.complain(Env.java:172) at vm.mlvm.share.MlvmTest.markTestFailedImpl(MlvmTest.java:265) at vm.mlvm.share.MlvmTest.markTestFailed(MlvmTest.java:247) at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.verifyTimeOrder(INDIFY_Test.java:296) at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.run(INDIFY_Test.java:401) at vm.mlvm.share.MlvmTestExecutor.runMlvmTestInstance(MlvmTestExecutor.java:382) at vm.mlvm.share.MlvmTestExecutor.runMlvmTest(MlvmTestExecutor.java:327) at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:244) at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:186) at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:157) at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:325) at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.main(INDIFY_Test.java:424) at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) at java.base/java.lang.reflect.Method.invoke(Method.java:580) at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138) at java.base/java.lang.Thread.run(Thread.java:1570) ### TRACE 1: MH.invoke() <= Direct call: Good. ### TRACE 1: MH.invokeExact() <= invokedynamic instruction: Good. # ERROR: Failed runs: 1 of 1 The following stacktrace is for failure analysis. nsk.share.TestFailure: Failed runs: 1 of 1 at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:431) at nsk.share.Log.complain(Log.java:402) at vm.mlvm.share.Env.complain(Env.java:164) at vm.mlvm.share.MlvmTestExecutor.runMlvmTestInstance(MlvmTestExecutor.java:408) at vm.mlvm.share.MlvmTestExecutor.runMlvmTest(MlvmTestExecutor.java:327) at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:244) at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:186) at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:157) at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:325) at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.main(INDIFY_Test.java:424) at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) at java.base/java.lang.reflect.Method.invoke(Method.java:580) at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138) at java.base/java.lang.Thread.run(Thread.java:1570) ### TRACE 1: TEST FAILED #> #> SUMMARY: Following errors occured #> during test execution: #> # ERROR: Test marked failed at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.verifyTimeOrder(INDIFY_Test.java:296): # ERROR: MH.invoke() invocation time order (31.2 ns) is greater than of Direct call(1.6 ns)! # ERROR: Failed runs: 1 of 1 ----------System.err:(0/0)---------- ----------rerun:(40/7162)*----------
24-09-2023
Deferring this to JDK 20 for now because it's a long standing issue and we are getting closer to the fork. If the fix is ready in time for JDK 19, the fix version needs to be reset.
18-05-2022
Here's a log file snippet for the jdk-18+3-54-tier7 sighting: vmTestbase/vm/mlvm/mixed/stress/regression/b6969574/INDIFY_Test.java # ERROR: Test marked failed at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.verifyTimeOrder(INDIFY_Test.java:296): # ERROR: MH.invokeExact() invocation time order (187.3 ns) is greater than of invokedynamic instruction(16.8 ns)! The following stacktrace is for failure analysis. nsk.share.TestFailure: Test marked failed at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.verifyTimeOrder(INDIFY_Test.java:296): MH.invokeExact() invocation time order (187.3 ns) is greater than of invokedynamic instruction(16.8 ns)! at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:432) at nsk.share.Log.complain(Log.java:403) at nsk.share.Log.complain(Log.java:416) at vm.mlvm.share.Env.complain(Env.java:172) at vm.mlvm.share.MlvmTest.markTestFailedImpl(MlvmTest.java:265) at vm.mlvm.share.MlvmTest.markTestFailed(MlvmTest.java:247) at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.verifyTimeOrder(INDIFY_Test.java:296) at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.run(INDIFY_Test.java:402) at vm.mlvm.share.MlvmTestExecutor.runMlvmTestInstance(MlvmTestExecutor.java:382) at vm.mlvm.share.MlvmTestExecutor.runMlvmTest(MlvmTestExecutor.java:327) at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:244) at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:186) at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:157) at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:325) at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.main(INDIFY_Test.java:424) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:568) at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127) at java.base/java.lang.Thread.run(Thread.java:833) ### TRACE 1: MH.invokeExact() <= invokedynamic instruction: Good. # ERROR: Failed runs: 1 of 1 The following stacktrace is for failure analysis. nsk.share.TestFailure: Failed runs: 1 of 1 at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:432) at nsk.share.Log.complain(Log.java:403) at vm.mlvm.share.Env.complain(Env.java:164) at vm.mlvm.share.MlvmTestExecutor.runMlvmTestInstance(MlvmTestExecutor.java:408) at vm.mlvm.share.MlvmTestExecutor.runMlvmTest(MlvmTestExecutor.java:327) at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:244) at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:186) at vm.mlvm.share.MlvmTestExecutor.launch(MlvmTestExecutor.java:157) at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:325) at vm.mlvm.mixed.stress.regression.b6969574.INDIFY_Test.main(INDIFY_Test.java:424) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:568) at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127) at java.base/java.lang.Thread.run(Thread.java:833) ### TRACE 1: TEST FAILED
24-06-2021
This failure did not happen in jdk-17+18-1483-tier7 so I've labeled this failure as 'intermittent'.
15-04-2021
This failure has happened in two Tier7 job sets in a row so far so I have removed the 'intermittent' label.
15-04-2021