eclipse-openj9 / openj9

Eclipse OpenJ9: A Java Virtual Machine for OpenJDK that's optimized for small footprint, fast start-up, and high throughput. Builds on Eclipse OMR (https://github.com/eclipse/omr) and combines with the Extensions for OpenJDK for OpenJ9 repo.
Other
3.27k stars 721 forks source link

jdk21 OpenJDK reflection failures #20200

Open pshipton opened 3 hours ago

pshipton commented 3 hours ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_aarch64_mac_OMR_testList_0/125/ jdk_lang java/lang/StackWalker/DumpStackTest.java java/lang/Thread/virtual/Reflection.java java/lang/invoke/callerSensitive/Main.java jdk/internal/vm/TestTranslatedException.java

java/lang/StackWalker/DumpStackTest.java

14:24:03  --- Actual ---
14:24:03  java.base/java.lang.Thread.getStackTrace(Thread.java:2483)
14:24:03  DumpStackTest.test(DumpStackTest.java:90)
14:24:03  DumpStackTest.main(DumpStackTest.java:43)
14:24:03  java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
14:24:03  java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:75)
14:24:03  java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:52)
14:24:03  java.base/java.lang.reflect.Method.invoke(Method.java:586)
14:24:03  com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
14:24:03  java.base/java.lang.Thread.run(Thread.java:1595)
14:24:03  --- Expected ---
14:24:03  java.lang.Thread.getStackTrace(Thread.java)
14:24:03  DumpStackTest.test(DumpStackTest.java)
14:24:03  DumpStackTest.main(DumpStackTest.java)
14:24:03  jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java)
14:24:03  java.lang.reflect.Method.invoke(Method.java)
14:24:03  java.lang.Thread.run(Thread.java)
14:24:03  STDERR:
14:24:03  java.lang.RuntimeException: StackTraceElements mismatch at index 3. Expected [jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java)], but get [java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)]
14:24:03    at DumpStackTest.assertEquals(DumpStackTest.java:217)
14:24:03    at DumpStackTest.assertStackTrace(DumpStackTest.java:209)
14:24:03    at DumpStackTest.test(DumpStackTest.java:90)
14:24:03    at DumpStackTest.main(DumpStackTest.java:43)

java/lang/Thread/virtual/Reflection.java

14:43:43  STARTED    Reflection::testInvokeStatic6 'testInvokeStatic6()'
14:43:43  
14:43:43  TEST RESULT: Error. Agent error: java.lang.Exception: Agent 26 timed out with a timeout of 960 seconds; check console log for any additional details

java/lang/invoke/callerSensitive/Main.java

14:21:43  java.lang.RuntimeException: class jdk.test.MethodInvokeTest$Caller1 should be a hidden class
14:21:43    at csm/jdk.test.MethodInvokeTest.assertTrue(MethodInvokeTest.java:208)
14:21:43    at csm/jdk.test.MethodInvokeTest.checkInjectedInvoker(MethodInvokeTest.java:187)
14:21:43    at csm/jdk.test.MethodInvokeTest.reflectMethodCall(MethodInvokeTest.java:99)
14:21:43    at csm/jdk.test.MethodInvokeTest.main(MethodInvokeTest.java:64)

jdk/internal/vm/TestTranslatedException.java

14:28:27  test jdk.internal.vm.test.TestTranslatedException.encodeDecodeTest(): failure
14:28:27  java.lang.AssertionError: expected [65] but found [34]
14:28:27    at org.testng.Assert.fail(Assert.java:99)
14:28:27    at org.testng.Assert.failNotEquals(Assert.java:1037)
14:28:27    at org.testng.Assert.assertEqualsImpl(Assert.java:140)
14:28:27    at org.testng.Assert.assertEquals(Assert.java:122)
14:28:27    at org.testng.Assert.assertEquals(Assert.java:907)
14:28:27    at org.testng.Assert.assertEquals(Assert.java:917)
14:28:27    at jdk.internal.vm.test.TestTranslatedException.assertThrowableEquals(TestTranslatedException.java:169)
14:28:27    at jdk.internal.vm.test.TestTranslatedException.encodeDecode(TestTranslatedException.java:145)
14:28:27    at jdk.internal.vm.test.TestTranslatedException.encodeDecodeTest(TestTranslatedException.java:60)

https://github.com/eclipse-openj9/openj9/compare/8393fab...5bf2f17a1db Guessing https://github.com/eclipse-openj9/openj9/pull/20159

r30shah commented 3 hours ago

This is related to https://github.com/eclipse-openj9/openj9/pull/20159 , I looked at most of the failures, most of the test expects a method related to Direct Method Handle in the call stack which would not be there with switch to old reflection, hence this fails.

One concerning failure is in java/lang/Thread/virtual/Reflection.java which @fengxue-IS is helping taking a look at. Will revert back the commit if soon if we can not find fix / solution soon.

pshipton commented 3 hours ago

We can't have test failures in the builds, so even if they are expected failures we need to take action to either fix the test or exclude it.

r30shah commented 3 hours ago

We can't have test failures in the builds, so even if they are expected failures we need to take action to either fix the test or exclude it.

Yes understood and agree, if the fix for the failure with Virtual thread reflection test is simple enough, I will go over and disable the test which are expected to fail - Or else, will revert the commit.

fengxue-IS commented 1 hour ago

This is related to #20159 , I looked at most of the failures, most of the test expects a method related to Direct Method Handle in the call stack which would not be there with switch to old reflection, hence this fails.

One concerning failure is in java/lang/Thread/virtual/Reflection.java which @fengxue-IS is helping taking a look at. Will revert back the commit if soon if we can not find fix / solution soon.

The test hang in this case because the old reflection code path uses jdk/internal/reflect/NativeMethodAccessorImpl.invoke0(Native Method) to dispatch the call. invoke0 gets translated into a JNI call to JVM_InvokeMethod which pins the virtual thread to carrierThread as there are native frames on the stack hence preventing the vthread from unmounting.

There isn't anything broken with the code as this is the expected behaviour for virtual threads. We should consider modifying the test (or excluding this testInvokeStatic6 subtest).

One thing to note is that while the test is an edge case using custom scheduler with single carrier thread. this same issue of pinning can also occur for other use cases where reflection is used.

r30shah commented 1 hour ago

Thanks a lot @fengxue-IS for the analysis. Given that this behaviour would not be limited to this edge case and issue can occur with other cases trying to use reflection I will open up PR to revert it back once I confirm to document the performance issue.