openj9
openj9 copied to clipboard
eclipse-openj9
OpenJDK util/concurrent/locks/LockSupport/ParkLoops timeout
https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.openjdk_aarch64_linux_Nightly/152/ - cent8-aarch64-3
jdk_util_0 -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:+UseCompressedOops
java/util/concurrent/locks/LockSupport/ParkLoops.java
https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk17_j9_sanity.openjdk_aarch64_linux_Nightly/152/openjdk_test_output.tar.gz
22:18:54 ACTION: main -- Error. Agent error: java.lang.Exception: Agent 6 timed out with a timeout of 960 seconds; check console log for any additional details
22:18:54 REASON: Assumed action based on file name: run main ParkLoops
22:18:54 TIME: 961.679 seconds
22:18:54 messages:
22:18:54 command: main ParkLoops
22:18:54 reason: Assumed action based on file name: run main ParkLoops
22:18:54 Mode: agentvm
22:18:54 Agent id: 6
22:18:54 Timeout refired 960 times
22:18:54 Timeout information:
22:18:54 Running jcmd on process 1007525
22:18:54 Dump written to /home/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_aarch64_linux_Nightly/aqa-tests/TKG/output_16478268119056/jdk_util_0/work/scratch/1/core.20220320.221850.1007525.0001.dmp
22:18:54 Running jstack on process 1007525
22:18:54 2022-03-20T22:18:50.577120977
22:18:54 Virtual machine: 1007525 JVM information:
22:18:54 JRE 17 Linux aarch64-64-Bit Compressed References 20220321_163 (JIT enabled, AOT enabled)
22:18:54 OpenJ9 - 1621137e347
22:18:54 OMR - 644b9078b90
22:18:54 JCL - 10a3045ff7d based on jdk-17.0.3+4
22:18:54
22:18:54 "main" prio=5 Id=1 WAITING
22:18:54 at [email protected]/java.lang.Object.wait(Native Method)
22:18:54 at [email protected]/java.lang.Object.wait(Object.java:219)
22:18:54 at [email protected]/java.lang.Thread.join(Thread.java:769)
22:18:54 at app//com.sun.javatest.regtest.agent.MainActionHelper.runClass(MainActionHelper.java:198)
22:18:54 at app//com.sun.javatest.regtest.agent.AgentServer.doMain(AgentServer.java:306)
22:18:54 at app//com.sun.javatest.regtest.agent.AgentServer.run(AgentServer.java:233)
22:18:54 at app//com.sun.javatest.regtest.agent.AgentServer.main(AgentServer.java:70)
22:18:54
22:18:54 "JIT Compilation Thread-000" prio=10 Id=3 RUNNABLE
22:18:54
22:18:54 "JIT Compilation Thread-001 Suspended" prio=10 Id=4 RUNNABLE
22:18:54
22:18:54 "JIT Compilation Thread-002 Suspended" prio=10 Id=5 RUNNABLE
22:18:54
22:18:54 "JIT Compilation Thread-003 Suspended" prio=10 Id=6 RUNNABLE
22:18:54
22:18:54 "JIT Compilation Thread-004 Suspended" prio=10 Id=7 RUNNABLE
22:18:54
22:18:54 "JIT Compilation Thread-005 Suspended" prio=10 Id=8 RUNNABLE
22:18:54
22:18:54 "JIT Compilation Thread-006 Suspended" prio=10 Id=9 RUNNABLE
22:18:54
22:18:54 "JIT Diagnostic Compilation Thread-007 Suspended" prio=10 Id=10 RUNNABLE
22:18:54
22:18:54 "JIT-SamplerThread" prio=10 Id=11 TIMED_WAITING
22:18:54
22:18:54 "IProfiler" prio=5 Id=12 RUNNABLE
22:18:54
22:18:54 "Common-Cleaner" prio=8 Id=2 TIMED_WAITING
22:18:54 at [email protected]/java.lang.Object.wait(Native Method)
22:18:54 at [email protected]/java.lang.Object.wait(Object.java:219)
22:18:54 at [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:138)
22:18:54 at [email protected]/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:140)
22:18:54 at [email protected]/java.lang.Thread.run(Thread.java:889)
22:18:54 at [email protected]/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:162)
22:18:54
22:18:54 "Finalizer thread" prio=5 Id=13 RUNNABLE
22:18:54
22:18:54 "Concurrent Mark Helper" prio=1 Id=14 RUNNABLE
22:18:54
22:18:54 "GC Worker" prio=5 Id=15 RUNNABLE
22:18:54
22:18:54 "GC Worker" prio=5 Id=16 RUNNABLE
22:18:54
22:18:54 "GC Worker" prio=5 Id=17 RUNNABLE
22:18:54
22:18:54 "GC Worker" prio=5 Id=18 RUNNABLE
22:18:54
22:18:54 "GC Worker" prio=5 Id=19 RUNNABLE
22:18:54
22:18:54 "GC Worker" prio=5 Id=20 RUNNABLE
22:18:54
22:18:54 "GC Worker" prio=5 Id=21 RUNNABLE
22:18:54
22:18:54 "Attach API wait loop" prio=10 Id=24 RUNNABLE
22:18:54 at [email protected]/openj9.internal.tools.attach.target.IPC.waitSemaphore(Native Method)
22:18:54 at [email protected]/openj9.internal.tools.attach.target.CommonDirectory.waitSemaphore(CommonDirectory.java:264)
22:18:54 at [email protected]/openj9.internal.tools.attach.target.WaitLoop.waitForNotification(WaitLoop.java:66)
22:18:54 at [email protected]/openj9.internal.tools.attach.target.WaitLoop.run(WaitLoop.java:157)
22:18:54
22:18:54 "pool-1-thread-1" prio=5 Id=25 TIMED_WAITING
22:18:54 at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
22:18:54 at [email protected]/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:252)
22:18:54 at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1672)
22:18:54 at [email protected]/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182)
22:18:54 at [email protected]/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
22:18:54 at [email protected]/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1062)
22:18:54 at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1122)
22:18:54 at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
22:18:54 at [email protected]/java.lang.Thread.run(Thread.java:889)
22:18:54
22:18:54 "ClassCache Reaper" prio=5 Id=36 WAITING
22:18:54 at [email protected]/java.lang.Object.wait(Native Method)
22:18:54 at [email protected]/java.lang.Object.wait(Object.java:219)
22:18:54 at [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:138)
22:18:54 at [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:110)
22:18:54 at [email protected]/java.io.ClassCache$Reaper.run(ClassCache.java:234)
22:18:54 at [email protected]/java.lang.Thread.run(Thread.java:889)
22:18:54
22:18:54 "AgentVMThread" prio=5 Id=10538 WAITING
22:18:54 at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
22:18:54 at [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:211)
22:18:54 at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:715)
22:18:54 at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1047)
22:18:54 at [email protected]/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:230)
22:18:54 at ParkLoops.main(ParkLoops.java:124)
22:18:54 at [email protected]/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
22:18:54 at [email protected]/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
22:18:54 at [email protected]/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
22:18:54 at [email protected]/java.lang.reflect.Method.invoke(Method.java:568)
22:18:54 at app//com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
22:18:54 at [email protected]/java.lang.Thread.run(Thread.java:889)
22:18:54
22:18:54 "pool-16-thread-2" prio=5 Id=10540 RUNNABLE
22:18:54 at [email protected]/java.util.concurrent.atomic.AtomicReferenceArray.get(AtomicReferenceArray.java:101)
22:18:54 at ParkLoops$Unparker.run(ParkLoops.java:104)
22:18:54 at [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
22:18:54 at [email protected]/java.util.concurrent.FutureTask.run(FutureTask.java:264)
22:18:54 at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
22:18:54 at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
22:18:54 at [email protected]/java.lang.Thread.run(Thread.java:889)
22:18:54
22:18:54 "pool-16-thread-4" prio=5 Id=10542 RUNNABLE
22:18:54 at ParkLoops$Unparker.run(ParkLoops.java:109)
22:18:54 at [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
22:18:54 at [email protected]/java.util.concurrent.FutureTask.run(FutureTask.java:264)
22:18:54 at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
22:18:54 at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
22:18:54 at [email protected]/java.lang.Thread.run(Thread.java:889)
22:18:54
22:18:54 "pool-16-thread-6" prio=5 Id=10544 RUNNABLE
22:18:54 at [email protected]/java.util.concurrent.atomic.AtomicReferenceArray.get(AtomicReferenceArray.java:101)
22:18:54 at ParkLoops$Unparker.run(ParkLoops.java:104)
22:18:54 at [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
22:18:54 at [email protected]/java.util.concurrent.FutureTask.run(FutureTask.java:264)
22:18:54 at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
22:18:54 at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
22:18:54 at [email protected]/java.lang.Thread.run(Thread.java:889)
22:18:54
22:18:54 "pool-16-thread-8" prio=5 Id=10546 RUNNABLE
22:18:54 at [email protected]/java.util.concurrent.atomic.AtomicReferenceArray.get(AtomicReferenceArray.java:101)
22:18:54 at ParkLoops$Unparker.run(ParkLoops.java:104)
22:18:54 at [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
22:18:54 at [email protected]/java.util.concurrent.FutureTask.run(FutureTask.java:264)
22:18:54 at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
22:18:54 at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
22:18:54 at [email protected]/java.lang.Thread.run(Thread.java:889)
22:18:54
22:18:54 "file lock watchdog" prio=10 Id=10548 TIMED_WAITING
22:18:54 at [email protected]/java.lang.Object.wait(Native Method)
22:18:54 at [email protected]/java.lang.Object.wait(Object.java:219)
22:18:54 at [email protected]/java.util.TimerThread.mainLoop(Timer.java:563)
22:18:54 at [email protected]/java.util.TimerThread.run(Timer.java:516)
22:18:54
22:18:54 "Attachment portNumber: 33141" prio=10 Id=10549 RUNNABLE
22:18:54 at [email protected]/openj9.internal.tools.attach.target.DiagnosticUtils.dumpAllThreadsImpl(Native Method)
22:18:54 at [email protected]/openj9.internal.tools.attach.target.DiagnosticUtils.getThreadInfo(DiagnosticUtils.java:245)
22:18:54 at [email protected]/openj9.internal.tools.attach.target.DiagnosticUtils.executeDiagnosticCommand(DiagnosticUtils.java:181)
22:18:54 at [email protected]/openj9.internal.tools.attach.target.Attachment.doCommand(Attachment.java:248)
22:18:54 at [email protected]/openj9.internal.tools.attach.target.Attachment.run(Attachment.java:159)
22:18:54
22:18:54
22:18:54 --- Timeout information end.
https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0/146 jdk_util_1 java/util/concurrent/locks/LockSupport/ParkLoops.java
https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0/146/openjdk_test_output.tar.gz
01:54:32 Timeout information:
01:54:32 Running jcmd on process 5204
01:54:32 Dump written to C:\Users\jenkins\workspace\Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0\aqa-tests\TKG\output_17068351132203\jdk_util_1\work\scratch\2_74\core.20240202.015410.5204.0001.dmp
01:54:32 Dump written to C:\Users\jenkins\workspace\Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0\aqa-tests\TKG\output_17068351132203\jdk_util_1\work\scratch\2_74\javacore.20240202.015423.5204.0002.txt
01:54:32 Running jstack on process 5204
01:54:32 2024-02-02T01:54:25.169578700
01:54:32 Virtual machine: 5204 JVM information:
01:54:32 JRE 21 Windows Server 2019 amd64-64-Bit 20240201_164 (JIT enabled, AOT enabled)
01:54:32 OpenJ9 - edbf0e1a5bc
01:54:32 OMR - cbf3bf87cba
01:54:32 JCL - 83ef2a1a0da based on jdk-21.0.2+13
01:54:32
01:54:32 "main" prio=5 Id=2 WAITING
01:54:32 at [email protected]/java.lang.Object.waitImpl(Native Method)
01:54:32 at [email protected]/java.lang.Object.wait(Object.java:255)
01:54:32 at [email protected]/java.lang.Object.wait(Object.java:221)
01:54:32 at [email protected]/java.lang.Thread.join(Thread.java:2102)
01:54:32 at [email protected]/java.lang.Thread.join(Thread.java:2178)
01:54:32 at app//com.sun.javatest.regtest.agent.MainActionHelper.runClass(MainActionHelper.java:219)
01:54:32 at app//com.sun.javatest.regtest.agent.AgentServer.doMain(AgentServer.java:317)
01:54:32 at app//com.sun.javatest.regtest.agent.AgentServer.run(AgentServer.java:242)
01:54:32 at app//com.sun.javatest.regtest.agent.AgentServer.main(AgentServer.java:71)
01:54:32
01:54:32 "JIT Compilation Thread-000" prio=10 Id=4 RUNNABLE
01:54:32
01:54:32 "JIT Compilation Thread-001 Suspended" prio=10 Id=5 RUNNABLE
01:54:32
01:54:32 "JIT Compilation Thread-002 Suspended" prio=10 Id=6 RUNNABLE
01:54:32
01:54:32 "JIT Diagnostic Compilation Thread-003 Suspended" prio=10 Id=7 RUNNABLE
01:54:32
01:54:32 "JIT-SamplerThread" prio=10 Id=8 TIMED_WAITING
01:54:32
01:54:32 "IProfiler" prio=5 Id=9 RUNNABLE
01:54:32
01:54:32 "Common-Cleaner" prio=8 Id=3 TIMED_WAITING
01:54:32 at [email protected]/java.lang.Object.waitImpl(Native Method)
01:54:32 at [email protected]/java.lang.Object.wait(Object.java:255)
01:54:32 at [email protected]/java.lang.Object.wait(Object.java:221)
01:54:32 at [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:137)
01:54:32 at [email protected]/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:140)
01:54:32 at [email protected]/java.lang.Thread.run(Thread.java:1595)
01:54:32 at [email protected]/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)
01:54:32
01:54:32 "Concurrent Mark Helper" prio=1 Id=11 RUNNABLE
01:54:32
01:54:32 "Finalizer thread" prio=5 Id=10 RUNNABLE
01:54:32
01:54:32 "GC Worker" prio=5 Id=12 RUNNABLE
01:54:32
01:54:32 "GC Worker" prio=5 Id=13 RUNNABLE
01:54:32
01:54:32 "GC Worker" prio=5 Id=14 RUNNABLE
01:54:32
01:54:32 "Attach API wait loop" prio=10 Id=17 RUNNABLE
01:54:32 at [email protected]/openj9.internal.tools.attach.target.IPC.waitSemaphore(Native Method)
01:54:32 at [email protected]/openj9.internal.tools.attach.target.CommonDirectory.waitSemaphore(CommonDirectory.java:264)
01:54:32 at [email protected]/openj9.internal.tools.attach.target.WaitLoop.waitForNotification(WaitLoop.java:66)
01:54:32 at [email protected]/openj9.internal.tools.attach.target.WaitLoop.run(WaitLoop.java:157)
01:54:32
01:54:32 "pool-1-thread-1" prio=5 Id=18 TIMED_WAITING
01:54:32 at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
01:54:32 at [email protected]/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:269)
01:54:32 at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1758)
01:54:32 at [email protected]/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182)
01:54:32 at [email protected]/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
01:54:32 at [email protected]/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1070)
01:54:32 at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
01:54:32 at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
01:54:32 at [email protected]/java.lang.Thread.run(Thread.java:1595)
01:54:32
01:54:32 "AgentVMThread" prio=5 Id=19 WAITING
01:54:32 at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
01:54:32 at [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:221)
01:54:32 at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:754)
01:54:32 at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1099)
01:54:32 at [email protected]/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:230)
01:54:32 at ParkLoops.main(ParkLoops.java:124)
01:54:32 at [email protected]/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
01:54:32 at [email protected]/java.lang.reflect.Method.invoke(Method.java:586)
01:54:32 at app//com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:333)
01:54:32 at [email protected]/java.lang.Thread.run(Thread.java:1595)
01:54:32
01:54:32 "pool-2-thread-1" prio=5 Id=20 WAITING
01:54:32 at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
01:54:32 at [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)
01:54:32 at ParkLoops$Parker.run(ParkLoops.java:77)
01:54:32 at [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
01:54:32 at [email protected]/java.util.concurrent.FutureTask.run(FutureTask.java:317)
01:54:32 at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
01:54:32 at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
01:54:32 at [email protected]/java.lang.Thread.run(Thread.java:1595)
01:54:32
01:54:32 "pool-2-thread-3" prio=5 Id=22 WAITING
01:54:32 at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
01:54:32 at [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)
01:54:32 at ParkLoops$Parker.run(ParkLoops.java:77)
01:54:32 at [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
01:54:32 at [email protected]/java.util.concurrent.FutureTask.run(FutureTask.java:317)
01:54:32 at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
01:54:32 at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
01:54:32 at [email protected]/java.lang.Thread.run(Thread.java:1595)
01:54:32
01:54:32 "pool-2-thread-7" prio=5 Id=26 WAITING
01:54:32 at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
01:54:32 at [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)
01:54:32 at ParkLoops$Parker.run(ParkLoops.java:77)
01:54:32 at [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
01:54:32 at [email protected]/java.util.concurrent.FutureTask.run(FutureTask.java:317)
01:54:32 at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
01:54:32 at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
01:54:32 at [email protected]/java.lang.Thread.run(Thread.java:1595)
01:54:32
01:54:32 "file lock watchdog" prio=10 Id=29 TIMED_WAITING
01:54:32 at [email protected]/java.lang.Object.waitImpl(Native Method)
01:54:32 at [email protected]/java.lang.Object.wait(Object.java:255)
01:54:32 at [email protected]/java.lang.Object.wait(Object.java:221)
01:54:32 at [email protected]/java.util.TimerThread.mainLoop(Timer.java:570)
01:54:32 at [email protected]/java.util.TimerThread.run(Timer.java:523)
01:54:32
01:54:32 "Attachment portNumber: 63615" prio=10 Id=31 RUNNABLE
01:54:32 at [email protected]/openj9.internal.tools.attach.target.DiagnosticUtils.dumpAllThreadsImpl(Native Method)
01:54:32 at [email protected]/openj9.internal.tools.attach.target.DiagnosticUtils.getThreadInfo(DiagnosticUtils.java:249)
01:54:32 at [email protected]/openj9.internal.tools.attach.target.DiagnosticUtils.executeDiagnosticCommand(DiagnosticUtils.java:185)
01:54:32 at [email protected]/openj9.internal.tools.attach.target.Attachment.doCommand(Attachment.java:248)
01:54:32 at [email protected]/openj9.internal.tools.attach.target.Attachment.run(Attachment.java:159)
01:54:32
01:54:32
01:54:32 --- Timeout information end.
https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_s390x_linux_OpenJDK21_testList_0/13 jdk_util_1 java/util/concurrent/locks/LockSupport/ParkLoops.java
https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk21_j9_sanity.openjdk_s390x_linux_OpenJDK21_testList_0/13/openjdk_test_output.tar.gz
04:14:49 Timeout information:
04:14:49 Running jcmd on process 9537
04:14:49 Dump written to /home/jenkins/workspace/Test_openjdk21_j9_sanity.openjdk_s390x_linux_OpenJDK21_testList_0/aqa-tests/TKG/output_1706775141268/jdk_util_1/work/scratch/2/core.20240201.041357.9537.0001.dmp
04:14:49 Dump written to /home/jenkins/workspace/Test_openjdk21_j9_sanity.openjdk_s390x_linux_OpenJDK21_testList_0/aqa-tests/TKG/output_1706775141268/jdk_util_1/work/scratch/2/javacore.20240201.041443.9537.0002.txt
04:14:49 Running jstack on process 9537
04:14:49 2024-02-01T04:14:44.669962082
04:14:49 Virtual machine: 9537 JVM information:
04:14:49 JRE 21 Linux s390x-64-Bit 20240201_15 (JIT enabled, AOT enabled)
04:14:49 OpenJ9 - ac66d8cf7c5
04:14:49 OMR - cbf3bf87cba
04:14:49 JCL - 5f34c927f6a based on jdk-21.0.3+1
04:14:49
04:14:49 "main" prio=5 Id=2 WAITING
04:14:49 at [email protected]/java.lang.Object.waitImpl(Native Method)
04:14:49 at [email protected]/java.lang.Object.wait(Object.java:255)
04:14:49 at [email protected]/java.lang.Object.wait(Object.java:221)
04:14:49 at [email protected]/java.lang.Thread.join(Thread.java:2102)
04:14:49 at [email protected]/java.lang.Thread.join(Thread.java:2178)
04:14:49 at app//com.sun.javatest.regtest.agent.MainActionHelper.runClass(MainActionHelper.java:219)
04:14:49 at app//com.sun.javatest.regtest.agent.AgentServer.doMain(AgentServer.java:317)
04:14:49 at app//com.sun.javatest.regtest.agent.AgentServer.run(AgentServer.java:242)
04:14:49 at app//com.sun.javatest.regtest.agent.AgentServer.main(AgentServer.java:71)
04:14:49
04:14:49 "JIT Compilation Thread-000" prio=10 Id=4 RUNNABLE
04:14:49
04:14:49 "JIT Compilation Thread-001 Suspended" prio=10 Id=5 RUNNABLE
04:14:49
04:14:49 "JIT Compilation Thread-002 Suspended" prio=10 Id=6 RUNNABLE
04:14:49
04:14:49 "JIT Compilation Thread-003 Suspended" prio=10 Id=7 RUNNABLE
04:14:49
04:14:49 "JIT Compilation Thread-004 Suspended" prio=10 Id=8 RUNNABLE
04:14:49
04:14:49 "JIT Compilation Thread-005 Suspended" prio=10 Id=9 RUNNABLE
04:14:49
04:14:49 "JIT Compilation Thread-006 Suspended" prio=10 Id=10 RUNNABLE
04:14:49
04:14:49 "JIT Diagnostic Compilation Thread-007 Suspended" prio=10 Id=11 RUNNABLE
04:14:49
04:14:49 "JIT-SamplerThread" prio=10 Id=12 TIMED_WAITING
04:14:49
04:14:49 "IProfiler" prio=5 Id=13 RUNNABLE
04:14:49
04:14:49 "Common-Cleaner" prio=8 Id=3 TIMED_WAITING
04:14:49 at [email protected]/java.lang.Object.waitImpl(Native Method)
04:14:49 at [email protected]/java.lang.Object.wait(Object.java:255)
04:14:49 at [email protected]/java.lang.Object.wait(Object.java:221)
04:14:49 at [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:137)
04:14:49 at [email protected]/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:140)
04:14:49 at [email protected]/java.lang.Thread.run(Thread.java:1595)
04:14:49 at [email protected]/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)
04:14:49
04:14:49 "Finalizer thread" prio=5 Id=14 RUNNABLE
04:14:49
04:14:49 "Concurrent Mark Helper" prio=1 Id=15 RUNNABLE
04:14:49
04:14:49 "GC Worker" prio=5 Id=16 RUNNABLE
04:14:49
04:14:49 "GC Worker" prio=5 Id=17 RUNNABLE
04:14:49
04:14:49 "GC Worker" prio=5 Id=18 RUNNABLE
04:14:49
04:14:49 "Attach API wait loop" prio=10 Id=21 RUNNABLE
04:14:49 at [email protected]/openj9.internal.tools.attach.target.IPC.waitSemaphore(Native Method)
04:14:49 at [email protected]/openj9.internal.tools.attach.target.CommonDirectory.waitSemaphore(CommonDirectory.java:264)
04:14:49 at [email protected]/openj9.internal.tools.attach.target.WaitLoop.waitForNotification(WaitLoop.java:66)
04:14:49 at [email protected]/openj9.internal.tools.attach.target.WaitLoop.run(WaitLoop.java:157)
04:14:49
04:14:49 "pool-1-thread-1" prio=5 Id=22 TIMED_WAITING
04:14:49 at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
04:14:49 at [email protected]/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:269)
04:14:49 at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1758)
04:14:49 at [email protected]/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182)
04:14:49 at [email protected]/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
04:14:49 at [email protected]/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1070)
04:14:49 at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
04:14:49 at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
04:14:49 at [email protected]/java.lang.Thread.run(Thread.java:1595)
04:14:49
04:14:49 "ClassByNameCache Reaper" prio=5 Id=28 WAITING
04:14:49 at [email protected]/java.lang.Object.waitImpl(Native Method)
04:14:49 at [email protected]/java.lang.Object.wait(Object.java:255)
04:14:49 at [email protected]/java.lang.Object.wait(Object.java:221)
04:14:49 at [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:137)
04:14:49 at [email protected]/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:109)
04:14:49 at [email protected]/java.io.ClassByNameCache$Reaper.run(ClassByNameCache.java:232)
04:14:49 at [email protected]/java.lang.Thread.run(Thread.java:1595)
04:14:49
04:14:49 "AgentVMThread" prio=5 Id=363 WAITING
04:14:49 at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
04:14:49 at [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:221)
04:14:49 at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:754)
04:14:49 at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1099)
04:14:49 at [email protected]/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:230)
04:14:49 at ParkLoops.main(ParkLoops.java:124)
04:14:49 at [email protected]/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
04:14:49 at [email protected]/java.lang.reflect.Method.invoke(Method.java:586)
04:14:49 at app//com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:333)
04:14:49 at [email protected]/java.lang.Thread.run(Thread.java:1595)
04:14:49
04:14:49 "pool-28-thread-5" prio=5 Id=368 WAITING
04:14:49 at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
04:14:49 at [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)
04:14:49 at ParkLoops$Parker.run(ParkLoops.java:77)
04:14:49 at [email protected]/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
04:14:49 at [email protected]/java.util.concurrent.FutureTask.run(FutureTask.java:317)
04:14:49 at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
04:14:49 at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
04:14:49 at [email protected]/java.lang.Thread.run(Thread.java:1595)
04:14:49
04:14:49 "file lock watchdog" prio=10 Id=373 TIMED_WAITING
04:14:49 at [email protected]/java.lang.Object.waitImpl(Native Method)
04:14:49 at [email protected]/java.lang.Object.wait(Object.java:255)
04:14:49 at [email protected]/java.lang.Object.wait(Object.java:221)
04:14:49 at [email protected]/java.util.TimerThread.mainLoop(Timer.java:602)
04:14:49 at [email protected]/java.util.TimerThread.run(Timer.java:543)
04:14:49
04:14:49 "Attachment portNumber: 44500" prio=10 Id=375 RUNNABLE
04:14:49 at [email protected]/openj9.internal.tools.attach.target.DiagnosticUtils.dumpAllThreadsImpl(Native Method)
04:14:49 at [email protected]/openj9.internal.tools.attach.target.DiagnosticUtils.getThreadInfo(DiagnosticUtils.java:249)
04:14:49 at [email protected]/openj9.internal.tools.attach.target.DiagnosticUtils.executeDiagnosticCommand(DiagnosticUtils.java:185)
04:14:49 at [email protected]/openj9.internal.tools.attach.target.Attachment.doCommand(Attachment.java:248)
04:14:49 at [email protected]/openj9.internal.tools.attach.target.Attachment.run(Attachment.java:159)
04:14:49
04:14:49
04:14:49 --- Timeout information end.
These occurred in the 21.0.3+2 acceptance build.
https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_aarch64_mac_OpenJDK21_testList_0/11/ jdk_util_1 java/util/concurrent/locks/LockSupport/ParkLoops.java
Timeout but no diagnostics - Error getting data from 1473: Exception connecting to 1473
https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_mac_OpenJDK21_testList_0/11/ jdk_util_1 java/util/concurrent/locks/LockSupport/ParkLoops.java
Timeout but no diagnostic - Error getting data from 52794: Exception connecting to 52794
https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_mac_Nightly_testList_1/107 jdk_util_0 java/util/concurrent/locks/LockSupport/ParkLoops.java
Timeout no diagnostics
https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_mac_Nightly_testList_1/108 https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_2/153/
It looks like the test has completed but the test harness code is still running
It looks similar to https://github.com/eclipse-openj9/openj9/issues/9651 excpet that this test doesn't appear to do excessive GC
NVM, here is the issue
04:14:49 "AgentVMThread" prio=5 Id=363 WAITING
04:14:49 at [email protected]/jdk.internal.misc.Unsafe.park(Native Method)
04:14:49 at [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:221)
04:14:49 at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:754)
04:14:49 at [email protected]/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1099)
04:14:49 at [email protected]/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:230)
04:14:49 at ParkLoops.main(ParkLoops.java:124)
04:14:49 at [email protected]/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
04:14:49 at [email protected]/java.lang.reflect.Method.invoke(Method.java:586)
04:14:49 at app//com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:333)
04:14:49 at [email protected]/java.lang.Thread.run(Thread.java:1595)
It looks like the main thread is waiting to be notified by the worker threads. In the traces above there is still at least onme park thread remaining, none of the unparker threads are active.
-Xint https://openj9-jenkins.osuosl.org/job/Grinder/3300/ (0/30 failed) -Xjit https://openj9-jenkins.osuosl.org/job/Grinder/3301/ (4/30 failed)
My guess is that a call to unpark is being missed, perhaps being optimized out?
Gonna run a few more just to verify it cant be seen with -Xint https://openj9-jenkins.osuosl.org/job/Grinder/3302/ (60 runs) no faiures
60 runs with jit exclude on ParkLoops
https://openj9-jenkins.osuosl.org/job/Grinder/3303/ (two failures)
60 runs with OSR turned off https://openj9-jenkins.osuosl.org/job/Grinder/3304/ (3 failures)
80 runs excluding LockSupport compilation https://openj9-jenkins.osuosl.org/job/Grinder/3315/ no failures
More runs with -Xjit:exclude={ParkLoops.,java/util/concurrent/locks/LockSupport.} https://openj9-jenkins.osuosl.org/job/Grinder/3316/ (140 runs - 11 failures)
Retrying Xint https://openj9-jenkins.osuosl.org/job/Grinder/3317/ (200 runs) no failures
https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_2/158 - timeout
https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.openjdk_x86-64_windows_Nightly_testList_1/154 - timeout https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_0/160 - timeout https://openj9-jenkins.osuosl.org/job/Test_openjdk22_j9_sanity.openjdk_aarch64_mac_Personal_testList_0/2 - timeout
I've been running some internal grinders on this. I can't reproduce it with -Xjit:exclude={java/util/*} — internal grinder run 38140 — and I can reproduce it with -Xjit:limit={java/util/*} — internal grinder run 38191.
However, I could also reproduce the failure with -Xjit:exclude={java/util/concurrent/*} — internal grinder run 38150 — and -Xjit:exclude={ParkLoops.*|java/util/concurrent/locks/LockSupport.*} — internal grinder run 38126.
Still trying to narrow things down further.
It seems that, at the minimum, the following two methods must be compiled to reproduce the failure:
-
java/util/concurrent/locks/AbstractOwnableSynchronizer.getExclusiveOwnerThread()Ljava/lang/Thread; -
java/util/concurrent/locks/AbstractOwnableSynchronizer.setExclusiveOwnerThread(Ljava/lang/Thread;)V
I have managed to reproduce the failure with those rather trivial methods compiled with optLevel=noopt — internal grinder run 38272 (3/40 failures)
I modified the test so that the main method would wait a few minutes, and then throw a TestHangException if it found that the work hadn't been completed. Then I ran that modified test with -Xdump:system:events=throw+systhrow,filter=ParkLoops*. Unfortunately, I was not able to reproduce the failure in a grinder run with the -Xdump option (0/150), though I could still reproduce it (about 1/50) running the modified test without the option.
I was never able to reproduce the failure in grinder runs with x86-64_mac, aarch64_mac or x86-64_windows — only s390x_linux. However, the failures for s390x_linux seem to have disappeared after ibmruntimes/openj9-openjdk-jdk21#132 was merged, so I strongly suspect these failures were likely due to the race condition in java.lang.invoke.VarHandle.getMethodHandle described in issue #18882. See grinder run 3382 which fails 4/16 (still running) using a build before that pull request was merged and grinder run 3383 which fails 0/50 using a build after that pull request was merged.
As I mentioned above, I had been able to reproduce failures with only AbstractOwnableSynchronizer.getExclusiveOwnerThread and AbstractOwnableSynchronizer.setExclusiveOwnerThread compiled, so it might be there is some other problem that results in similar symptoms, but not so frequently. That could also be the cause of the original report of this hanging test case.
@pshipton, assuming that there haven't been any further failures reported for this test since the end of February, I would like to remove the blocker label, and remove this from the 0.44-release milestone.
I went ahead and closed it since the failure isn't seen any more. If you want an issue for further investigation, it might be better to create a new one specific to that. Otherwise, feel free to adjust the labels and move this issue.