jvmti/vthread/GetThreadStateMountedTest/GetThreadStateMountedTest JVMTI_THREAD_STATE_WAITING_INDEFINITELY JVMTI_THREAD_STATE_WAITING_WITH_TIMEOUT some mandatory bits are not set

pshipton commented 7 months ago

Internal build Internal build serviceability/jvmti/vthread/GetThreadStateMountedTest/GetThreadStateMountedTest.java

00:08:47  >>JVMTI_THREAD_STATE_WAITING_INDEFINITELY
00:08:47  suspend vthread (0)
00:08:47  suspended in WAITING state
00:08:47  Thread VirtualThread[#27]/runnable@ForkJoinPool-1-worker-1
00:08:47  cthread state(91):  ALIVE WAITING WAITING_INDEFINITELY
00:08:47  vthread state(100191):  ALIVE WAITING WAITING_INDEFINITELY IN_OBJECT_WAIT SUSPENDED
00:08:47  suspend cthread
00:08:47  cthread state(100091):  ALIVE WAITING WAITING_INDEFINITELY SUSPENDED
00:08:47  vthread state(100191):  ALIVE WAITING WAITING_INDEFINITELY IN_OBJECT_WAIT SUSPENDED
00:08:47  resume cthread
00:08:47  cthread state(91):  ALIVE WAITING WAITING_INDEFINITELY
00:08:47  vthread state(100191):  ALIVE WAITING WAITING_INDEFINITELY IN_OBJECT_WAIT SUSPENDED
00:08:47  interrupt vthread
00:08:47  cthread state(91):  ALIVE WAITING WAITING_INDEFINITELY
00:08:47  vthread state(300005):  ALIVE RUNNABLE SUSPENDED INTERRUPTED
00:08:47    ERROR: some mandatory bits are not set (190):  WAITING WAITING_INDEFINITELY IN_OBJECT_WAIT
00:08:47    ERROR: some unexpected bits are set (4):  RUNNABLE
00:08:47    expected 'strong' state (300191):  ALIVE WAITING WAITING_INDEFINITELY IN_OBJECT_WAIT SUSPENDED INTERRUPTED
00:08:47    expected 'weak' state (0): <none>
00:08:47  resume vthread
00:08:47  <<JVMTI_THREAD_STATE_WAITING_INDEFINITELY - FAILED
00:08:47  
00:08:47  >>JVMTI_THREAD_STATE_WAITING_WITH_TIMEOUT
00:08:47  suspend vthread (0)
00:08:47  suspended in WAITING state
00:08:47  Thread VirtualThread[#29]/runnable@ForkJoinPool-1-worker-2
00:08:47  cthread state(91):  ALIVE WAITING WAITING_INDEFINITELY
00:08:47  vthread state(1001a1):  ALIVE WAITING WAITING_WITH_TIMEOUT IN_OBJECT_WAIT SUSPENDED
00:08:47  suspend cthread
00:08:47  cthread state(100091):  ALIVE WAITING WAITING_INDEFINITELY SUSPENDED
00:08:47  vthread state(1001a1):  ALIVE WAITING WAITING_WITH_TIMEOUT IN_OBJECT_WAIT SUSPENDED
00:08:47  resume cthread
00:08:47  cthread state(91):  ALIVE WAITING WAITING_INDEFINITELY
00:08:47  vthread state(1001a1):  ALIVE WAITING WAITING_WITH_TIMEOUT IN_OBJECT_WAIT SUSPENDED
00:08:47  interrupt vthread
00:08:47  cthread state(91):  ALIVE WAITING WAITING_INDEFINITELY
00:08:47  vthread state(300005):  ALIVE RUNNABLE SUSPENDED INTERRUPTED
00:08:47    ERROR: some mandatory bits are not set (1a0):  WAITING WAITING_WITH_TIMEOUT IN_OBJECT_WAIT
00:08:47    ERROR: some unexpected bits are set (4):  RUNNABLE
00:08:47    expected 'strong' state (3001a1):  ALIVE WAITING WAITING_WITH_TIMEOUT IN_OBJECT_WAIT SUSPENDED INTERRUPTED
00:08:47    expected 'weak' state (0): <none>
00:08:47  resume vthread
00:08:47  <<JVMTI_THREAD_STATE_WAITING_WITH_TIMEOUT - FAILED

pshipton commented 7 months ago

@babsingh fyi

babsingh commented 7 months ago

It seems related to https://github.com/eclipse-openj9/openj9/pull/19076.
https://github.com/eclipse-openj9/openj9/pull/19186 is the potential fix which was merged an hour after the failing builds were launched.
@fengxue-IS Can you please launch appropriate grinders to confirm that https://github.com/eclipse-openj9/openj9/pull/19186 fixes this failure?

fengxue-IS commented 7 months ago

20x Grinder on zlinux 2/20 failed, looking into the failures

fengxue-IS commented 7 months ago

Test failed with the patch included are all due to IN_NATIVE being set on the vthread. looking into the changeset to see what could cause this

fengxue-IS commented 7 months ago

New failure output with patch included:

[2024-03-21T16:05:40.239Z] >>JVMTI_THREAD_STATE_RUNNABLE
[2024-03-21T16:05:40.239Z] Thread VirtualThread[#24]/runnable@ForkJoinPool-1-worker-1
[2024-03-21T16:05:40.239Z] cthread state(91):  ALIVE WAITING WAITING_INDEFINITELY
[2024-03-21T16:05:40.239Z] vthread state(400005):  ALIVE RUNNABLE IN_NATIVE
[2024-03-21T16:05:40.239Z]   ERROR: some unexpected bits are set (400000):  IN_NATIVE
[2024-03-21T16:05:40.239Z]   expected 'strong' state (5):  ALIVE RUNNABLE
[2024-03-21T16:05:40.239Z]   expected 'weak' state (0): <none>
[2024-03-21T16:05:40.239Z] suspend cthread
[2024-03-21T16:05:40.239Z] cthread state(100091):  ALIVE WAITING WAITING_INDEFINITELY SUSPENDED
[2024-03-21T16:05:40.239Z] vthread state(400005):  ALIVE RUNNABLE IN_NATIVE
[2024-03-21T16:05:40.239Z]   ERROR: some unexpected bits are set (400000):  IN_NATIVE
[2024-03-21T16:05:40.239Z]   expected 'strong' state (5):  ALIVE RUNNABLE
[2024-03-21T16:05:40.239Z]   expected 'weak' state (0): <none>
[2024-03-21T16:05:40.239Z] suspend vthread
[2024-03-21T16:05:40.239Z] cthread state(100091):  ALIVE WAITING WAITING_INDEFINITELY SUSPENDED
[2024-03-21T16:05:40.239Z] vthread state(500005):  ALIVE RUNNABLE SUSPENDED IN_NATIVE
[2024-03-21T16:05:40.239Z]   ERROR: some unexpected bits are set (400000):  IN_NATIVE
[2024-03-21T16:05:40.239Z]   expected 'strong' state (100005):  ALIVE RUNNABLE SUSPENDED
[2024-03-21T16:05:40.239Z]   expected 'weak' state (0): <none>
[2024-03-21T16:05:40.239Z] resume cthread
[2024-03-21T16:05:40.239Z] cthread state(91):  ALIVE WAITING WAITING_INDEFINITELY
[2024-03-21T16:05:40.239Z] vthread state(500005):  ALIVE RUNNABLE SUSPENDED IN_NATIVE
[2024-03-21T16:05:40.239Z]   ERROR: some unexpected bits are set (400000):  IN_NATIVE
[2024-03-21T16:05:40.239Z]   expected 'strong' state (100005):  ALIVE RUNNABLE SUSPENDED
[2024-03-21T16:05:40.239Z]   expected 'weak' state (0): <none>
[2024-03-21T16:05:40.239Z] interrupt vthread
[2024-03-21T16:05:40.239Z] cthread state(91):  ALIVE WAITING WAITING_INDEFINITELY
[2024-03-21T16:05:40.239Z] vthread state(700005):  ALIVE RUNNABLE SUSPENDED INTERRUPTED IN_NATIVE
[2024-03-21T16:05:40.239Z]   ERROR: some unexpected bits are set (400000):  IN_NATIVE
[2024-03-21T16:05:40.239Z]   expected 'strong' state (300005):  ALIVE RUNNABLE SUSPENDED INTERRUPTED
[2024-03-21T16:05:40.239Z]   expected 'weak' state (0): <none>
[2024-03-21T16:05:40.239Z] resume vthread
[2024-03-21T16:05:40.239Z] <<JVMTI_THREAD_STATE_RUNNABLE - FAILED

babsingh commented 7 months ago

https://docs.oracle.com/en/java/javase/21/docs/specs/jvmti.html

JVMTI_THREAD_STATE_IN_NATIVE: Thread is in native code--that is, a native method is running which has not called back into the VM or Java programming language code.
See the thread state rules in https://docs.oracle.com/en/java/javase/21/docs/specs/jvmti.html#GetThreadState. Having IN_NATIVE in the thread state is considered valid as per the JVMTI spec.
This behaviour is seen because our new behaviour allows a virtual thread to suspend in the middle of the mount/unmount phases

babsingh commented 7 months ago

Another note: the original failure reported in this issue has been resolved by https://github.com/eclipse-openj9/openj9/pull/19186.

fengxue-IS commented 7 months ago

The stacktrace of the failing vthread:

<1420c00>   !j9method 0x00000000012B6590   jdk/internal/misc/Unsafe.unpark(Ljava/lang/Object;)V
<1420c00>   !j9method 0x00000000012F0830   java/util/concurrent/locks/LockSupport.unpark(Ljava/lang/Thread;)V
<1420c00>   !j9method 0x0000000001333F70   java/util/concurrent/locks/AbstractQueuedSynchronizer.signalNext(Ljava/util/concurrent/locks/AbstractQueuedSynchronizer$Node;)V
<1420c00>   !j9method 0x00000000013341B0   java/util/concurrent/locks/AbstractQueuedSynchronizer.releaseShared(I)Z
<1420c00>   !j9method 0x0000000001484730   java/util/concurrent/CountDownLatch.countDown()V
<1420c00>   !j9method 0x000000000145BB70   GetThreadStateMountedTest.lambda$runnable$0(Ljava/util/concurrent/CountDownLatch;[Z)V
<1420c00>   !j9method 0x000000000145C4F0   GetThreadStateMountedTest$$Lambda/0x0000000093fa1a10.run()V
<1420c00>   !j9method 0x000000000145BAB0   GetThreadStateMountedTest.lambda$createPinnedVThread$6(Ljava/lang/Object;Ljava/lang/Runnable;)V
<1420c00>   !j9method 0x000000000145C7F0   GetThreadStateMountedTest$$Lambda/0x0000000093fa1bc0.run()V
<1420c00>   !j9method 0x00000000012DBC80   java/lang/Thread.runWith(Ljava/lang/Object;Ljava/lang/Runnable;)V
<1420c00>   !j9method 0x00000000012F7478   java/lang/VirtualThread.run(Ljava/lang/Runnable;)V
<1420c00>   !j9method 0x00000000014ADAF0   java/lang/VirtualThread$VThreadContinuation$1.run()V
<1420c00>   !j9method 0x0000000001306360   jdk/internal/vm/Continuation.enter(Ljdk/internal/vm/Continuation;)V
<1420c00>                           JNI call-in frame
<1420c00>                           Native method frame

Looking at the test failure it self, this is not a blocker or functional incorrectness. As jdk/internal/misc/Unsafe.unpark is implemented as an JNI call in OpenJ9, if the unparked thread called getThreadState before the vthread returned from unpark() call. We will get this error. This test failure is due to impl differences between RI and OpenJ9, which can either be fixed by updating test to use a spin wait mechanism instead of CountDownLatch. An INL/fastJNI for unpark which retains VMAccess can also be added on the VM side, but that would need more discussion on the impact.

Based on this, I will continue with backport of #19076 to 0.44

pshipton commented 7 months ago

Based on this, I will continue with backport of https://github.com/eclipse-openj9/openj9/issues/19091 to 0.44

Pls make this happen asap today.

tajila commented 6 months ago

The latest is that this is a test issue. We can modify the test to address this.

JasonFengJ9 commented 6 months ago

JDK22 s390x_linux(sles12s390x-svl-rt4-1)

[2024-04-26T05:28:39.545Z] variation: Mode650
[2024-04-26T05:28:39.545Z] JVM_OPTIONS:  -XX:-UseCompressedOops -Xverbosegclog 

[2024-04-26T05:32:20.225Z] TEST: serviceability/jvmti/vthread/GetThreadStateMountedTest/GetThreadStateMountedTest.java

[2024-04-26T05:32:20.226Z] STDOUT:
[2024-04-26T05:32:20.226Z] >>JVMTI_THREAD_STATE_RUNNABLE
[2024-04-26T05:32:20.226Z] Thread VirtualThread[#24]/runnable@ForkJoinPool-1-worker-1
[2024-04-26T05:32:20.226Z] cthread state(91):  ALIVE WAITING WAITING_INDEFINITELY
[2024-04-26T05:32:20.226Z] vthread state(400005):  ALIVE RUNNABLE IN_NATIVE
[2024-04-26T05:32:20.226Z]   ERROR: some unexpected bits are set (400000):  IN_NATIVE
[2024-04-26T05:32:20.226Z]   expected 'strong' state (5):  ALIVE RUNNABLE
[2024-04-26T05:32:20.226Z]   expected 'weak' state (0): <none>

[2024-04-26T05:32:20.226Z] STDERR:
[2024-04-26T05:32:20.226Z] java.lang.RuntimeException: Test failed, 5 errors
[2024-04-26T05:32:20.226Z]  at GetThreadStateMountedTest.main(GetThreadStateMountedTest.java:250)
[2024-04-26T05:32:20.226Z]  at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
[2024-04-26T05:32:20.226Z]  at java.base/java.lang.reflect.Method.invoke(Method.java:586)
[2024-04-26T05:32:20.226Z]  at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
[2024-04-26T05:32:20.226Z]  at java.base/java.lang.Thread.run(Thread.java:1582)
[2024-04-26T05:32:20.226Z] 
[2024-04-26T05:32:20.226Z] JavaTest Message: Test threw exception: java.lang.RuntimeException: Test failed, 5 errors

[2024-04-26T05:33:11.131Z] Test results: passed: 158; failed: 1
[2024-04-26T05:33:12.062Z] Report written to /home/jenkins/workspace/Test_openjdk22_j9_extended.openjdk_s390x_linux_testList_1/jvmtest/openjdk/report/html/report.html
[2024-04-26T05:33:12.062Z] Results written to /home/jenkins/workspace/Test_openjdk22_j9_extended.openjdk_s390x_linux_testList_1/aqa-tests/TKG/output_17141093187410/serviceability_jvmti_j9_1/work
[2024-04-26T05:33:12.062Z] Error: Some tests failed or other problems occurred.
[2024-04-26T05:33:12.062Z] -----------------------------------
[2024-04-26T05:33:12.062Z] serviceability_jvmti_j9_1_FAILED

babsingh commented 5 months ago

The initial failure reported in the issue has been fixed. The IN_NATIVE failure reported later is a test issue and doesn't block the 0.46 release. It also happens with the RI and is being tracked at OpenJDK: https://bugs.openjdk.org/browse/JDK-8318090. The RI has targeted JDK24 to fix the test. We will keep this issue open until the RI fixes the test. Moving this issue to the 0.48 release.

JasonFengJ9 commented 4 months ago

JDK22 s390x_linux(ubu22s390x-rt-1)

[2024-06-01T18:34:25.626Z] variation: Mode150
[2024-06-01T18:34:25.626Z] JVM_OPTIONS:  -XX:+UseCompressedOops -Xverbosegclog 

[2024-06-01T18:37:46.467Z] TEST: serviceability/jvmti/vthread/GetThreadStateMountedTest/GetThreadStateMountedTest.java

[2024-06-01T18:37:46.468Z] STDOUT:
[2024-06-01T18:37:46.468Z] >>JVMTI_THREAD_STATE_RUNNABLE
[2024-06-01T18:37:46.468Z] Thread VirtualThread[#24]/runnable@ForkJoinPool-1-worker-1
[2024-06-01T18:37:46.468Z] cthread state(91):  ALIVE WAITING WAITING_INDEFINITELY
[2024-06-01T18:37:46.468Z] vthread state(400005):  ALIVE RUNNABLE IN_NATIVE
[2024-06-01T18:37:46.468Z]   ERROR: some unexpected bits are set (400000):  IN_NATIVE
[2024-06-01T18:37:46.468Z]   expected 'strong' state (5):  ALIVE RUNNABLE
[2024-06-01T18:37:46.468Z]   expected 'weak' state (0): <none>
[2024-06-01T18:37:46.468Z] suspend cthread
[2024-06-01T18:37:46.468Z] cthread state(100091):  ALIVE WAITING WAITING_INDEFINITELY SUSPENDED
[2024-06-01T18:37:46.468Z] vthread state(400005):  ALIVE RUNNABLE IN_NATIVE
[2024-06-01T18:37:46.468Z]   ERROR: some unexpected bits are set (400000):  IN_NATIVE
[2024-06-01T18:37:46.468Z]   expected 'strong' state (5):  ALIVE RUNNABLE
[2024-06-01T18:37:46.468Z]   expected 'weak' state (0): <none>
[2024-06-01T18:37:46.468Z] suspend vthread
[2024-06-01T18:37:46.468Z] cthread state(100091):  ALIVE WAITING WAITING_INDEFINITELY SUSPENDED
[2024-06-01T18:37:46.468Z] vthread state(500005):  ALIVE RUNNABLE SUSPENDED IN_NATIVE
[2024-06-01T18:37:46.468Z]   ERROR: some unexpected bits are set (400000):  IN_NATIVE
[2024-06-01T18:37:46.468Z]   expected 'strong' state (100005):  ALIVE RUNNABLE SUSPENDED
[2024-06-01T18:37:46.468Z]   expected 'weak' state (0): <none>
[2024-06-01T18:37:46.468Z] resume cthread
[2024-06-01T18:37:46.468Z] cthread state(91):  ALIVE WAITING WAITING_INDEFINITELY
[2024-06-01T18:37:46.468Z] vthread state(500005):  ALIVE RUNNABLE SUSPENDED IN_NATIVE
[2024-06-01T18:37:46.468Z]   ERROR: some unexpected bits are set (400000):  IN_NATIVE
[2024-06-01T18:37:46.468Z]   expected 'strong' state (100005):  ALIVE RUNNABLE SUSPENDED
[2024-06-01T18:37:46.468Z]   expected 'weak' state (0): <none>
[2024-06-01T18:37:46.468Z] interrupt vthread
[2024-06-01T18:37:46.468Z] cthread state(91):  ALIVE WAITING WAITING_INDEFINITELY
[2024-06-01T18:37:46.468Z] vthread state(700005):  ALIVE RUNNABLE SUSPENDED INTERRUPTED IN_NATIVE
[2024-06-01T18:37:46.468Z]   ERROR: some unexpected bits are set (400000):  IN_NATIVE
[2024-06-01T18:37:46.468Z]   expected 'strong' state (300005):  ALIVE RUNNABLE SUSPENDED INTERRUPTED
[2024-06-01T18:37:46.468Z]   expected 'weak' state (0): <none>
[2024-06-01T18:37:46.468Z] resume vthread
[2024-06-01T18:37:46.468Z] <<JVMTI_THREAD_STATE_RUNNABLE - FAILED

[2024-06-01T18:37:46.469Z] TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Test failed, 5 errors
[2024-06-01T18:37:46.469Z] --------------------------------------------------
[2024-06-01T18:38:28.422Z] Test results: passed: 158; failed: 1
[2024-06-01T18:38:32.680Z] Report written to /home/jenkins/workspace/Test_openjdk22_j9_extended.openjdk_s390x_linux_testList_0/jvmtest/openjdk/report/html/report.html
[2024-06-01T18:38:32.680Z] Results written to /home/jenkins/workspace/Test_openjdk22_j9_extended.openjdk_s390x_linux_testList_0/aqa-tests/TKG/output_17172668635656/serviceability_jvmti_j9_0/work
[2024-06-01T18:38:32.680Z] Error: Some tests failed or other problems occurred.
[2024-06-01T18:38:32.680Z] -----------------------------------
[2024-06-01T18:38:32.680Z] serviceability_jvmti_j9_0_FAILED

llxia commented 1 month ago

re https://github.com/eclipse-openj9/openj9/issues/19203#issuecomment-2137663450, https://bugs.openjdk.org/browse/JDK-8318090 has not been fixed (targeted for JDK24). @pshipton should we move this to next release?

babsingh commented 1 month ago

should we move this to next release?

We should move it to the Java 24 milestone to match the RI.

eclipse-openj9 / openj9

jvmti/vthread/GetThreadStateMountedTest/GetThreadStateMountedTest JVMTI_THREAD_STATE_WAITING_INDEFINITELY JVMTI_THREAD_STATE_WAITING_WITH_TIMEOUT some mandatory bits are not set #19203