openj9 icon indicating copy to clipboard operation
openj9 copied to clipboard

Published 20 hours ago • verified publisher icon eclipse-openj9

jdk19 openjdk java/util/concurrent/tck/JSR166TestCase.java testAwaitUninterruptibly(ReentrantReadWriteLockTest): timed out waiting for thread to enter thread state WAITING

Open pshipton opened this issue 2 years ago • 3 comments

Failures in jdk-19+28 acceptance build. https://openj9-jenkins.osuosl.org/job/Pipeline-OpenJDK19-Acceptance/6/

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_aarch64_linux_OpenJDK19/4 jdk_util_1 java/util/concurrent/tck/JSR166TestCase.java

15:45:23  ACTION: junit -- Failed. Execution failed: `main' threw exception: java.lang.Exception: JUnit test failure
15:45:23  REASON: User specified action: run junit/othervm/timeout=1000 -Djava.security.manager=allow JSR166TestCase 
15:45:23  TIME:   94.395 seconds
15:45:23  messages:
15:45:23  command: junit -Djava.security.manager=allow JSR166TestCase
15:45:23  reason: User specified action: run junit/othervm/timeout=1000 -Djava.security.manager=allow JSR166TestCase 
15:45:23  Mode: othervm [/othervm specified]
15:45:23  Additional options from @modules: --add-modules java.management
15:45:23  elapsed time (seconds): 94.395
15:45:23  configuration:
15:45:23  Boot Layer
15:45:23    add modules: java.management
15:45:23  
15:45:23  STDOUT:
15:45:23  STDERR:
15:45:23  JavaTest Message: JUnit Failure: testAwaitUninterruptibly(ReentrantReadWriteLockTest): timed out waiting for thread to enter thread state WAITING
15:45:23  junit.framework.AssertionFailedError: timed out waiting for thread to enter thread state WAITING
15:45:23  	at junit.framework.Assert.fail(Assert.java:57)
15:45:23  	at junit.framework.TestCase.fail(TestCase.java:223)
15:45:23  	at JSR166TestCase.assertThreadBlocks(JSR166TestCase.java:1221)
15:45:23  	at ReentrantReadWriteLockTest.testAwaitUninterruptibly(ReentrantReadWriteLockTest.java:1070)
15:45:23  	at ReentrantReadWriteLockTest.testAwaitUninterruptibly(ReentrantReadWriteLockTest.java:1037)

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_aarch64_mac_OpenJDK19/3 https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_s390x_linux_OpenJDK19/4 https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_x86-64_linux_OpenJDK19/4

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_ppc64_aix_OpenJDK19/4 jdk_util_0 & jdk_util_1

19:38:51  ACTION: junit -- Error. Program `/home/jenkins/workspace/Test_openjdk19_j9_sanity.openjdk_ppc64_aix_OpenJDK19/openjdkbinary/j2sdk-image/bin/java' timed out (timeout set to 8000000ms, elapsed time including timeout handling was 10229994ms).
19:38:51  REASON: User specified action: run junit/othervm/timeout=1000 --add-opens java.base/java.util.concurrent=ALL-UNNAMED --add-opens java.base/java.lang=ALL-UNNAMED -Djsr166.testImplementationDetails=true JSR166TestCase 
19:38:51  TIME:   10230.013 seconds
19:38:51  messages:
19:38:51  command: junit --add-opens java.base/java.util.concurrent=ALL-UNNAMED --add-opens java.base/java.lang=ALL-UNNAMED -Djsr166.testImplementationDetails=true JSR166TestCase
19:38:51  reason: User specified action: run junit/othervm/timeout=1000 --add-opens java.base/java.util.concurrent=ALL-UNNAMED --add-opens java.base/java.lang=ALL-UNNAMED -Djsr166.testImplementationDetails=true JSR166TestCase 
19:38:51  Mode: othervm [/othervm specified]
19:38:51  Additional options from @modules: --add-modules java.management
19:38:51  Timeout information:
19:38:51  Running jcmd on process 13959668
19:38:51  Timeout refired 300 times
19:38:51  Error getting data from 13959668: Exception connecting to 13959668
19:38:51  Usage : jcmd <vmid> <arguments>
19:38:51  
19:38:51     -J : supply arguments to the Java VM running jcmd
19:38:51     -l : list JVM processes on the local machine
19:38:51     -h : print this help message
19:38:51  
19:38:51     <vmid> : Attach API VM ID as shown in jps or other Attach API-based tools
19:38:52  
19:38:52     arguments:
19:38:52        help : print the list of diagnostic commands
19:38:52        help <command> : print help for the specific command
19:38:52        <command> [command arguments] : command from the list returned by "help"
19:38:52  
19:38:52  list JVM processes on the local machine. Default behavior when no options are specified.
19:38:52  
19:38:52  NOTE: this utility might significantly affect the performance of the target JVM.
19:38:52      The available diagnostic commands are determined by
19:38:52      the target VM and may vary between VMs.

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_ppc64le_linux_OpenJDK19/4 jdk_util_0 & jdk_util_1

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_x86-64_windows_OpenJDK19/4

16:13:09  Looks like we're stuck running test: testAwaitUninterruptibly(ReentrantReadWriteLockTest)
16:13:09  ------ stacktrace dump start ------
16:13:09  "Thread-0" prio=5 Id=2 WAITING
16:13:09  	at java.base@19-internal/java.lang.Object.wait(Native Method)
16:13:09  	at java.base@19-internal/java.lang.Object.wait(Object.java:219)
16:13:09  	at java.base@19-internal/java.lang.Thread.join(Thread.java:2146)
16:13:09  	at java.base@19-internal/java.lang.Thread.join(Thread.java:2222)
16:13:09  	at app//com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:74)
16:13:09  "JIT Compilation Thread-000" prio=10 Id=4 RUNNABLE
16:13:09  "JIT Compilation Thread-001 Suspended" prio=10 Id=5 RUNNABLE
16:13:09  "JIT Compilation Thread-002 Suspended" prio=10 Id=6 RUNNABLE
16:13:09  "JIT Compilation Thread-003 Suspended" prio=10 Id=7 RUNNABLE
16:13:09  "JIT Compilation Thread-004 Suspended" prio=10 Id=8 RUNNABLE
16:13:09  "JIT Compilation Thread-005 Suspended" prio=10 Id=9 RUNNABLE
16:13:09  "JIT Compilation Thread-006 Suspended" prio=10 Id=10 RUNNABLE
16:13:09  "JIT Diagnostic Compilation Thread-007 Suspended" prio=10 Id=11 RUNNABLE
16:13:09  "JIT-SamplerThread" prio=10 Id=12 RUNNABLE
16:13:09  "IProfiler" prio=5 Id=13 RUNNABLE
16:13:09  "Concurrent Mark Helper" prio=1 Id=14 RUNNABLE
16:13:09  "Finalizer thread" prio=5 Id=15 RUNNABLE
16:13:09  "GC Worker" prio=5 Id=16 RUNNABLE
16:13:09  "GC Worker" prio=5 Id=17 RUNNABLE
16:13:09  "GC Worker" prio=5 Id=18 RUNNABLE
16:13:09  "GC Worker" prio=5 Id=19 RUNNABLE
16:13:09  "GC Worker" prio=5 Id=20 RUNNABLE
16:13:09  "GC Worker" prio=5 Id=21 RUNNABLE
16:13:09  "GC Worker" prio=5 Id=22 RUNNABLE
16:13:09  "Attach API wait loop" prio=10 Id=25 RUNNABLE
16:13:09  	at java.base@19-internal/openj9.internal.tools.attach.target.IPC.waitSemaphore(Native Method)
16:13:09  	at java.base@19-internal/openj9.internal.tools.attach.target.CommonDirectory.waitSemaphore(CommonDirectory.java:264)
16:13:09  	at java.base@19-internal/openj9.internal.tools.attach.target.WaitLoop.waitForNotification(WaitLoop.java:66)
16:13:09  	at java.base@19-internal/openj9.internal.tools.attach.target.WaitLoop.run(WaitLoop.java:157)
16:13:09  "MainThread" prio=5 Id=27 RUNNABLE
16:13:09  	at java.base@19-internal/java.lang.Thread.sleepImpl(Native Method)
16:13:09  	at java.base@19-internal/java.lang.Thread.sleep0(Thread.java:477)
16:13:09  	at java.base@19-internal/java.lang.Thread.sleep(Thread.java:472)
16:13:09  	at app//JSR166TestCase.delay(JSR166TestCase.java:1032)
16:13:09  	at app//JSR166TestCase.assertThreadBlocks(JSR166TestCase.java:1211)
16:13:09  	at app//ReentrantReadWriteLockTest.testAwaitUninterruptibly(ReentrantReadWriteLockTest.java:1070)
16:13:09  	at app//ReentrantReadWriteLockTest.testAwaitUninterruptibly(ReentrantReadWriteLockTest.java:1037)
16:13:09  	at java.base@19-internal/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
16:13:09  	at java.base@19-internal/java.lang.reflect.Method.invoke(Method.java:578)
16:13:09  	at app//junit.framework.TestCase.runTest(TestCase.java:177)
16:13:09  	at app//JSR166TestCase.runTest(JSR166TestCase.java:382)
16:13:09  	at app//junit.framework.TestCase.runBare(TestCase.java:142)
16:13:09  	at app//JSR166TestCase.runBare(JSR166TestCase.java:373)
16:13:09  	at app//junit.framework.TestResult$1.protect(TestResult.java:122)
16:13:09  	at app//junit.framework.TestResult.runProtected(TestResult.java:142)
16:13:09  	at app//junit.framework.TestResult.run(TestResult.java:125)
16:13:09  	at app//junit.framework.TestCase.run(TestCase.java:130)
16:13:09  	at app//junit.framework.TestSuite.runTest(TestSuite.java:241)
16:13:09  	at app//junit.framework.TestSuite.run(TestSuite.java:236)
16:13:09  	at app//junit.framework.TestSuite.runTest(TestSuite.java:241)
16:13:09  	at app//junit.framework.TestSuite.run(TestSuite.java:236)
16:13:09  	at app//org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:90)
16:13:09  	at app//org.junit.runners.Suite.runChild(Suite.java:128)
16:13:09  	at app//org.junit.runners.Suite.runChild(Suite.java:27)
16:13:09  	at app//org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
16:13:09  	at app//org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
16:13:09  	at app//org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
16:13:09  	at app//org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
16:13:09  	at app//org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
16:13:09  	at app//org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
16:13:09  	at app//org.junit.runners.ParentRunner.run(ParentRunner.java:413)
16:13:09  	at app//org.junit.runner.JUnitCore.run(JUnitCore.java:137)
16:13:09  	at app//org.junit.runner.JUnitCore.run(JUnitCore.java:115)
16:13:09  	at app//org.junit.runner.JUnitCore.run(JUnitCore.java:105)
16:13:09  	at app//org.junit.runner.JUnitCore.runClasses(JUnitCore.java:62)
16:13:09  	at app//org.junit.runner.JUnitCore.runClasses(JUnitCore.java:49)
16:13:09  	at app//com.sun.javatest.regtest.agent.JUnitRunner.main(JUnitRunner.java:76)
16:13:09  	at app//com.sun.javatest.regtest.agent.JUnitRunner.main(JUnitRunner.java:43)
16:13:09  	at java.base@19-internal/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
16:13:09  	at java.base@19-internal/java.lang.reflect.Method.invoke(Method.java:578)
16:13:09  	at app//com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
16:13:09  	at java.base@19-internal/java.lang.Thread.run(Thread.java:1573)
16:13:09  "ClassByNameCache Reaper" prio=5 Id=728 WAITING
16:13:09  	at java.base@19-internal/java.lang.Object.wait(Native Method)
16:13:09  	at java.base@19-internal/java.lang.Object.wait(Object.java:219)
16:13:09  	at java.base@19-internal/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:137)
16:13:09  	at java.base@19-internal/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:109)
16:13:09  	at java.base@19-internal/java.io.ClassByNameCache$Reaper.run(ClassByNameCache.java:232)
16:13:09  	at java.base@19-internal/java.lang.Thread.run(Thread.java:1573)
16:13:09  "Thread-504" prio=5 Id=1624 WAITING
16:13:09  	at java.base@19-internal/jdk.internal.misc.Unsafe.park(Native Method)
16:13:09  	at java.base@19-internal/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)
16:13:09  	at java.base@19-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(AbstractQueuedSynchronizer.java:506)
16:13:09  	at java.base@19-internal/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3744)
16:13:09  	at java.base@19-internal/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3689)
16:13:09  	at java.base@19-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitUninterruptibly(AbstractQueuedSynchronizer.java:1580)
16:13:09  	at app//ReentrantReadWriteLockTest$31.realRun(ReentrantReadWriteLockTest.java:1050)
16:13:09  	at app//JSR166TestCase$CheckedRunnable.run(JSR166TestCase.java:1698)
16:13:09  	at java.base@19-internal/java.lang.Thread.run(Thread.java:1573)
16:13:09  "Thread-505" prio=5 Id=1625 RUNNABLE
16:13:09  	at java.base@19-internal/jdk.internal.misc.Unsafe.park(Native Method)
16:13:09  	at java.base@19-internal/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)
16:13:09  	at java.base@19-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(AbstractQueuedSynchronizer.java:506)
16:13:09  	at java.base@19-internal/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3744)
16:13:09  	at java.base@19-internal/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3689)
16:13:09  	at java.base@19-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitUninterruptibly(AbstractQueuedSynchronizer.java:1580)
16:13:09  	at app//ReentrantReadWriteLockTest$32.realRun(ReentrantReadWriteLockTest.java:1060)
16:13:09  	at app//JSR166TestCase$CheckedRunnable.run(JSR166TestCase.java:1698)
16:13:09  	at java.base@19-internal/java.lang.Thread.run(Thread.java:1573)
16:13:09  ------ stacktrace dump end ------
16:13:09  JavaTest Message: JUnit Failure: testAwaitUninterruptibly(ReentrantReadWriteLockTest): timed out waiting for thread to enter thread state WAITING
16:13:09  junit.framework.AssertionFailedError: timed out waiting for thread to enter thread state WAITING
16:13:09  	at junit.framework.Assert.fail(Assert.java:57)
16:13:09  	at junit.framework.TestCase.fail(TestCase.java:223)
16:13:09  	at java.base/java.lang.AbstractStringBuilder.appendChars(AbstractStringBuilder.java:1776)
16:13:09  	at ReentrantReadWriteLockTest.testAwaitUninterruptibly(ReentrantReadWriteLockTest.java:1070)
16:13:09  	at ReentrantReadWriteLockTest.testAwaitUninterruptibly(ReentrantReadWriteLockTest.java:1037)

pshipton avatar Jun 30 '22 15:06 pshipton

Set high priority since it's blocking sanity.openjdk from running green.

pshipton avatar Jun 30 '22 16:06 pshipton

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_ppc64_aix_OpenJDK19/5 https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_ppc64le_linux_OpenJDK19/5 https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_x86-64_mac_OpenJDK19/5

pshipton avatar Jul 05 '22 19:07 pshipton

Also seen at internal build job/Test_openjdk19_j9_sanity.openjdk_x86-64_mac_testList_1/6/

openjdk version "19-beta" 2022-09-20
IBM Semeru Runtime Open Edition 19+28-202207050535 (build 19-beta+28-202207050535)
Eclipse OpenJ9 VM 19+28-202207050535 (build master-0e480f25e, JRE 19 Mac OS X amd64-64-Bit Compressed References 20220705_18 (JIT enabled, AOT enabled)
OpenJ9   - 0e480f25e
OMR      - d018241d7
JCL      - 28e60ccf5a based on jdk-19+28)

[2022-07-05T07:30:17.997Z] TEST: java/util/concurrent/tck/JSR166TestCase.java

[2022-07-05T07:30:18.001Z] STDERR:
[2022-07-05T07:30:18.001Z] JavaTest Message: JUnit Failure: testAwaitUninterruptibly_fair(ReentrantLockTest): timed out waiting for thread to enter thread state WAITING
[2022-07-05T07:30:18.001Z] junit.framework.AssertionFailedError: timed out waiting for thread to enter thread state WAITING
[2022-07-05T07:30:18.001Z] 	at junit.framework.Assert.fail(Assert.java:57)
[2022-07-05T07:30:18.001Z] 	at junit.framework.TestCase.fail(TestCase.java:223)
[2022-07-05T07:30:18.001Z] 	at JSR166TestCase.assertThreadBlocks(JSR166TestCase.java:1221)
[2022-07-05T07:30:18.001Z] 	at ReentrantLockTest.testAwaitUninterruptibly(ReentrantLockTest.java:954)
[2022-07-05T07:30:18.001Z] 	at ReentrantLockTest.testAwaitUninterruptibly_fair(ReentrantLockTest.java:922)
[2022-07-05T07:30:18.001Z] 	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)

JasonFengJ9 avatar Jul 07 '22 14:07 JasonFengJ9

@JasonFengJ9 does this still fail?

tajila avatar Nov 03 '22 17:11 tajila

The test passes locally. We can re-enable the test:

  • JDK19: https://github.com/adoptium/aqa-tests/blob/26b24753e1587b474180af2070bdff4759509b27/openjdk/excludes/ProblemList_openjdk19-openj9.txt#L442
  • JDK20: https://github.com/adoptium/aqa-tests/blob/26b24753e1587b474180af2070bdff4759509b27/openjdk/excludes/ProblemList_openjdk20-openj9.txt#L483

babsingh avatar Nov 03 '22 17:11 babsingh

The the test passes locally. We can re-enable the test:

@babsingh I will create a PR to enable it.

JasonFengJ9 avatar Nov 03 '22 18:11 JasonFengJ9

Created https://github.com/adoptium/aqa-tests/pull/4116 to enable java/util/concurrent/tck/JSR166TestCase.java except windows which matches ProblemList_openjdk19.txt for RI.

JasonFengJ9 avatar Nov 03 '22 18:11 JasonFengJ9

Seems it's still failing. Pls exclude it again. https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_aarch64_mac_Nightly/46

20:28:54  JavaTest Message: JUnit Failure: testAwaitUninterruptibly_fair(ReentrantLockTest): timed out waiting for thread to enter thread state WAITING
20:28:54  junit.framework.AssertionFailedError: timed out waiting for thread to enter thread state WAITING
20:28:54  	at junit.framework.Assert.fail(Assert.java:57)
20:28:54  	at junit.framework.TestCase.fail(TestCase.java:223)
20:28:54  	at JSR166TestCase.assertThreadBlocks(JSR166TestCase.java:1221)
20:28:54  	at ReentrantLockTest.testAwaitUninterruptibly(ReentrantLockTest.java:954)
20:28:54  	at ReentrantLockTest.testAwaitUninterruptibly_fair(ReentrantLockTest.java:922)

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_ppc64le_linux_Nightly/42/ https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_s390x_linux_Nightly/44/ https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_x86-64_linux_Nightly/42/

pshipton avatar Nov 07 '22 14:11 pshipton

Disabled again via https://github.com/adoptium/aqa-tests/pull/4120. The failure is intermittent. More investigation is required. The timeout may happen due to the GC race condition which was mentioned last week. fyi @LinHu2016. The other reason may be the transition to the RI's j.l.Thread.

babsingh avatar Nov 07 '22 15:11 babsingh

@babsingh don't forget to add the "test excluded" label when excluding tests.

pshipton avatar Nov 07 '22 15:11 pshipton

@hangshao0 Can you please take a look at this https://github.com/eclipse-openj9/openj9/issues/15465

tajila avatar Nov 22 '22 16:11 tajila

Looking at the java stack:

"Thread-505" prio=5 Id=1625 RUNNABLE
16:13:09  	at java.base@19-internal/jdk.internal.misc.Unsafe.park(Native Method)
16:13:09  	at java.base@19-internal/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)
16:13:09  	at java.base@19-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(AbstractQueuedSynchronizer.java:506)
16:13:09  	at java.base@19-internal/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3744)
16:13:09  	at java.base@19-internal/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3689)
16:13:09  	at java.base@19-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitUninterruptibly(AbstractQueuedSynchronizer.java:1580)
16:13:09  	at app//ReentrantReadWriteLockTest$32.realRun(ReentrantReadWriteLockTest.java:1060)
16:13:09  	at app//JSR166TestCase$CheckedRunnable.run(JSR166TestCase.java:1698)
16:13:09  	at java.base@19-internal/java.lang.Thread.run(Thread.java:1573)

We are already inside Unsafe.park() but the WAITING state is not set. The native code to set the state is: https://github.com/eclipse-openj9/openj9/blob/55c52ff26d9a8755b9de00704dee2b7f6543a041/runtime/oti/VMAccess.hpp#L196-L221.

It seems that we never reach VM_VMAccess::setPublicFlags(vmThread, flags).

hangshao0 avatar Nov 22 '22 21:11 hangshao0 

!j9vmthread 0x7f198091f400
J9VMThread at 0x7f198091f400 {
  Fields for J9VMThread:
        ...
        0x90: struct J9ThreadMonitor* publicFlagsMutex = !j9threadmonitor 0x00007F1A1C22A078
        0x98: UDATA publicFlags = 0x0000000000008020 (32800)
        0xa0: UDATA compressObjectReferences = 0x0000000000000000 (0)
        0xa8: struct J9Object* threadObject = !j9object 0x00007F1A1A2BA058 // java/lang/Thread
        ...
        0x140: struct J9Thread* osThread = !j9thread 0x00007F19805569D0
        ....
!j9thread 0x7f19805569d0
J9Thread at 0x7f19805569d0 {
  Fields for J9Thread:
        ...
        0x420: U64 flags = 0x0000000001000804 (16779268)  <--------- J9THREAD_FLAG_INTERRUPTED is set.
        ....

The thread entered Unsafe.park(), but with J9THREAD_FLAG_INTERRUPTED set. The thread won't park. It continued running.

Looking at the thread object, Thread.interrupted is false:

!j9object 0x00007F1A1A2BA058
!J9Object 0x00007F1A1A2BA058 {
        struct J9Class* clazz = !j9class 0x7F1A1C1CD100 // java/lang/Thread
        Object flags = 0x00000008;
        J lockword = 0x0000000000000000 (offset = 0) (java/lang/Object) <hidden>
        J eetop = 0x00007F198091F400 (offset = 8) (java/lang/Thread)
        J tid = 0x0000000000000669 (offset = 16) (java/lang/Thread)
        Ljava/lang/String; name = !fj9object 0x7f1a1a2ba5f8 (offset = 40) (java/lang/Thread)
        Z interrupted = 0x00000000 (offset = 152) (java/lang/Thread)

So we are in an incorrect state that Thread.interrupted is false, while J9THREAD_FLAG_INTERRUPTED is set on J9thread. It will never be parked by Unsafe.park().

hangshao0 avatar Nov 28 '22 16:11 hangshao0

There is a race condition. One thread is interrupting the target thread (setting Thread.interrupted to true and J9THREAD_FLAG_INTERRUPTED flag): https://github.com/ibmruntimes/openj9-openjdk-jdk19/blob/720d5357766d6cbb5dda08b469809da633f39129/src/java.base/share/classes/java/lang/Thread.java#L1757-L1759

Another thread is clearing the interruption (set Thread.interrupted to false and clear J9THREAD_FLAG_INTERRUPTED flag): https://github.com/ibmruntimes/openj9-openjdk-jdk19/blob/720d5357766d6cbb5dda08b469809da633f39129/src/java.base/share/classes/java/lang/Thread.java#L1821-L1822. However, it is not done inside interruptLock.

hangshao0 avatar Nov 29 '22 16:11 hangshao0

The issue goes away with https://github.com/ibmruntimes/openj9-openjdk-jdk19/pull/51

hangshao0 avatar Nov 29 '22 19:11 hangshao0

@hangshao0 The test needs to be re-enabled, and then the test excluded tag should be removed.

  • JDK19: https://github.com/adoptium/aqa-tests/blob/a74405ca1262c4e50ea0a88e9cb27ade2dd60179/openjdk/excludes/ProblemList_openjdk19-openj9.txt#L443
  • JDK20: https://github.com/adoptium/aqa-tests/blob/a74405ca1262c4e50ea0a88e9cb27ade2dd60179/openjdk/excludes/ProblemList_openjdk20-openj9.txt#L483

babsingh avatar Dec 06 '22 00:12 babsingh

PR to re-enable the test: https://github.com/adoptium/aqa-tests/pull/4187

hangshao0 avatar Dec 06 '22 16:12 hangshao0

PR to re-enable the test: https://github.com/adoptium/aqa-tests/pull/4187

Merged. Closing this issue.

hangshao0 avatar Dec 06 '22 21:12 hangshao0