search

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.28k stars 721 forks source link

OpenJDK util/concurrent/locks/LockSupport/ParkLoops timeout #14752

Closed pshipton closed 7 months ago

pshipton commented 2 years ago

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 java.base@17.0.3-internal/java.lang.Object.wait(Native Method)
22:18:54    at java.base@17.0.3-internal/java.lang.Object.wait(Object.java:219)
22:18:54    at java.base@17.0.3-internal/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 java.base@17.0.3-internal/java.lang.Object.wait(Native Method)
22:18:54    at java.base@17.0.3-internal/java.lang.Object.wait(Object.java:219)
22:18:54    at java.base@17.0.3-internal/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:138)
22:18:54    at java.base@17.0.3-internal/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:140)
22:18:54    at java.base@17.0.3-internal/java.lang.Thread.run(Thread.java:889)
22:18:54    at java.base@17.0.3-internal/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 java.base@17.0.3-internal/openj9.internal.tools.attach.target.IPC.waitSemaphore(Native Method)
22:18:54    at java.base@17.0.3-internal/openj9.internal.tools.attach.target.CommonDirectory.waitSemaphore(CommonDirectory.java:264)
22:18:54    at java.base@17.0.3-internal/openj9.internal.tools.attach.target.WaitLoop.waitForNotification(WaitLoop.java:66)
22:18:54    at java.base@17.0.3-internal/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 java.base@17.0.3-internal/jdk.internal.misc.Unsafe.park(Native Method)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:252)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1672)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1062)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1122)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
22:18:54    at java.base@17.0.3-internal/java.lang.Thread.run(Thread.java:889)
22:18:54  
22:18:54  "ClassCache Reaper" prio=5 Id=36 WAITING
22:18:54    at java.base@17.0.3-internal/java.lang.Object.wait(Native Method)
22:18:54    at java.base@17.0.3-internal/java.lang.Object.wait(Object.java:219)
22:18:54    at java.base@17.0.3-internal/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:138)
22:18:54    at java.base@17.0.3-internal/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:110)
22:18:54    at java.base@17.0.3-internal/java.io.ClassCache$Reaper.run(ClassCache.java:234)
22:18:54    at java.base@17.0.3-internal/java.lang.Thread.run(Thread.java:889)
22:18:54  
22:18:54  "AgentVMThread" prio=5 Id=10538 WAITING
22:18:54    at java.base@17.0.3-internal/jdk.internal.misc.Unsafe.park(Native Method)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.locks.LockSupport.park(LockSupport.java:211)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:715)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1047)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:230)
22:18:54    at ParkLoops.main(ParkLoops.java:124)
22:18:54    at java.base@17.0.3-internal/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
22:18:54    at java.base@17.0.3-internal/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
22:18:54    at java.base@17.0.3-internal/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
22:18:54    at java.base@17.0.3-internal/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 java.base@17.0.3-internal/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 java.base@17.0.3-internal/java.util.concurrent.atomic.AtomicReferenceArray.get(AtomicReferenceArray.java:101)
22:18:54    at ParkLoops$Unparker.run(ParkLoops.java:104)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.FutureTask.run(FutureTask.java:264)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
22:18:54    at java.base@17.0.3-internal/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 java.base@17.0.3-internal/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.FutureTask.run(FutureTask.java:264)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
22:18:54    at java.base@17.0.3-internal/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 java.base@17.0.3-internal/java.util.concurrent.atomic.AtomicReferenceArray.get(AtomicReferenceArray.java:101)
22:18:54    at ParkLoops$Unparker.run(ParkLoops.java:104)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.FutureTask.run(FutureTask.java:264)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
22:18:54    at java.base@17.0.3-internal/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 java.base@17.0.3-internal/java.util.concurrent.atomic.AtomicReferenceArray.get(AtomicReferenceArray.java:101)
22:18:54    at ParkLoops$Unparker.run(ParkLoops.java:104)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.FutureTask.run(FutureTask.java:264)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
22:18:54    at java.base@17.0.3-internal/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
22:18:54    at java.base@17.0.3-internal/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 java.base@17.0.3-internal/java.lang.Object.wait(Native Method)
22:18:54    at java.base@17.0.3-internal/java.lang.Object.wait(Object.java:219)
22:18:54    at java.base@17.0.3-internal/java.util.TimerThread.mainLoop(Timer.java:563)
22:18:54    at java.base@17.0.3-internal/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 java.base@17.0.3-internal/openj9.internal.tools.attach.target.DiagnosticUtils.dumpAllThreadsImpl(Native Method)
22:18:54    at java.base@17.0.3-internal/openj9.internal.tools.attach.target.DiagnosticUtils.getThreadInfo(DiagnosticUtils.java:245)
22:18:54    at java.base@17.0.3-internal/openj9.internal.tools.attach.target.DiagnosticUtils.executeDiagnosticCommand(DiagnosticUtils.java:181)
22:18:54    at java.base@17.0.3-internal/openj9.internal.tools.attach.target.Attachment.doCommand(Attachment.java:248)
22:18:54    at java.base@17.0.3-internal/openj9.internal.tools.attach.target.Attachment.run(Attachment.java:159)
22:18:54  
22:18:54  
22:18:54  --- Timeout information end.
pshipton commented 8 months ago

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 java.base@21.0.2-internal/java.lang.Object.waitImpl(Native Method)
01:54:32    at java.base@21.0.2-internal/java.lang.Object.wait(Object.java:255)
01:54:32    at java.base@21.0.2-internal/java.lang.Object.wait(Object.java:221)
01:54:32    at java.base@21.0.2-internal/java.lang.Thread.join(Thread.java:2102)
01:54:32    at java.base@21.0.2-internal/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 java.base@21.0.2-internal/java.lang.Object.waitImpl(Native Method)
01:54:32    at java.base@21.0.2-internal/java.lang.Object.wait(Object.java:255)
01:54:32    at java.base@21.0.2-internal/java.lang.Object.wait(Object.java:221)
01:54:32    at java.base@21.0.2-internal/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:137)
01:54:32    at java.base@21.0.2-internal/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:140)
01:54:32    at java.base@21.0.2-internal/java.lang.Thread.run(Thread.java:1595)
01:54:32    at java.base@21.0.2-internal/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 java.base@21.0.2-internal/openj9.internal.tools.attach.target.IPC.waitSemaphore(Native Method)
01:54:32    at java.base@21.0.2-internal/openj9.internal.tools.attach.target.CommonDirectory.waitSemaphore(CommonDirectory.java:264)
01:54:32    at java.base@21.0.2-internal/openj9.internal.tools.attach.target.WaitLoop.waitForNotification(WaitLoop.java:66)
01:54:32    at java.base@21.0.2-internal/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 java.base@21.0.2-internal/jdk.internal.misc.Unsafe.park(Native Method)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:269)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1758)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1070)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
01:54:32    at java.base@21.0.2-internal/java.lang.Thread.run(Thread.java:1595)
01:54:32  
01:54:32  "AgentVMThread" prio=5 Id=19 WAITING
01:54:32    at java.base@21.0.2-internal/jdk.internal.misc.Unsafe.park(Native Method)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.locks.LockSupport.park(LockSupport.java:221)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:754)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1099)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:230)
01:54:32    at ParkLoops.main(ParkLoops.java:124)
01:54:32    at java.base@21.0.2-internal/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
01:54:32    at java.base@21.0.2-internal/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 java.base@21.0.2-internal/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 java.base@21.0.2-internal/jdk.internal.misc.Unsafe.park(Native Method)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)
01:54:32    at ParkLoops$Parker.run(ParkLoops.java:77)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.FutureTask.run(FutureTask.java:317)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
01:54:32    at java.base@21.0.2-internal/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 java.base@21.0.2-internal/jdk.internal.misc.Unsafe.park(Native Method)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)
01:54:32    at ParkLoops$Parker.run(ParkLoops.java:77)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.FutureTask.run(FutureTask.java:317)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
01:54:32    at java.base@21.0.2-internal/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 java.base@21.0.2-internal/jdk.internal.misc.Unsafe.park(Native Method)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)
01:54:32    at ParkLoops$Parker.run(ParkLoops.java:77)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.FutureTask.run(FutureTask.java:317)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
01:54:32    at java.base@21.0.2-internal/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
01:54:32    at java.base@21.0.2-internal/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 java.base@21.0.2-internal/java.lang.Object.waitImpl(Native Method)
01:54:32    at java.base@21.0.2-internal/java.lang.Object.wait(Object.java:255)
01:54:32    at java.base@21.0.2-internal/java.lang.Object.wait(Object.java:221)
01:54:32    at java.base@21.0.2-internal/java.util.TimerThread.mainLoop(Timer.java:570)
01:54:32    at java.base@21.0.2-internal/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 java.base@21.0.2-internal/openj9.internal.tools.attach.target.DiagnosticUtils.dumpAllThreadsImpl(Native Method)
01:54:32    at java.base@21.0.2-internal/openj9.internal.tools.attach.target.DiagnosticUtils.getThreadInfo(DiagnosticUtils.java:249)
01:54:32    at java.base@21.0.2-internal/openj9.internal.tools.attach.target.DiagnosticUtils.executeDiagnosticCommand(DiagnosticUtils.java:185)
01:54:32    at java.base@21.0.2-internal/openj9.internal.tools.attach.target.Attachment.doCommand(Attachment.java:248)
01:54:32    at java.base@21.0.2-internal/openj9.internal.tools.attach.target.Attachment.run(Attachment.java:159)
01:54:32  
01:54:32  
01:54:32  --- Timeout information end.
pshipton commented 8 months ago

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 java.base@21.0.3-internal/java.lang.Object.waitImpl(Native Method)
04:14:49    at java.base@21.0.3-internal/java.lang.Object.wait(Object.java:255)
04:14:49    at java.base@21.0.3-internal/java.lang.Object.wait(Object.java:221)
04:14:49    at java.base@21.0.3-internal/java.lang.Thread.join(Thread.java:2102)
04:14:49    at java.base@21.0.3-internal/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 java.base@21.0.3-internal/java.lang.Object.waitImpl(Native Method)
04:14:49    at java.base@21.0.3-internal/java.lang.Object.wait(Object.java:255)
04:14:49    at java.base@21.0.3-internal/java.lang.Object.wait(Object.java:221)
04:14:49    at java.base@21.0.3-internal/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:137)
04:14:49    at java.base@21.0.3-internal/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:140)
04:14:49    at java.base@21.0.3-internal/java.lang.Thread.run(Thread.java:1595)
04:14:49    at java.base@21.0.3-internal/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 java.base@21.0.3-internal/openj9.internal.tools.attach.target.IPC.waitSemaphore(Native Method)
04:14:49    at java.base@21.0.3-internal/openj9.internal.tools.attach.target.CommonDirectory.waitSemaphore(CommonDirectory.java:264)
04:14:49    at java.base@21.0.3-internal/openj9.internal.tools.attach.target.WaitLoop.waitForNotification(WaitLoop.java:66)
04:14:49    at java.base@21.0.3-internal/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 java.base@21.0.3-internal/jdk.internal.misc.Unsafe.park(Native Method)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:269)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1758)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1070)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
04:14:49    at java.base@21.0.3-internal/java.lang.Thread.run(Thread.java:1595)
04:14:49  
04:14:49  "ClassByNameCache Reaper" prio=5 Id=28 WAITING
04:14:49    at java.base@21.0.3-internal/java.lang.Object.waitImpl(Native Method)
04:14:49    at java.base@21.0.3-internal/java.lang.Object.wait(Object.java:255)
04:14:49    at java.base@21.0.3-internal/java.lang.Object.wait(Object.java:221)
04:14:49    at java.base@21.0.3-internal/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:137)
04:14:49    at java.base@21.0.3-internal/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:109)
04:14:49    at java.base@21.0.3-internal/java.io.ClassByNameCache$Reaper.run(ClassByNameCache.java:232)
04:14:49    at java.base@21.0.3-internal/java.lang.Thread.run(Thread.java:1595)
04:14:49  
04:14:49  "AgentVMThread" prio=5 Id=363 WAITING
04:14:49    at java.base@21.0.3-internal/jdk.internal.misc.Unsafe.park(Native Method)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.locks.LockSupport.park(LockSupport.java:221)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:754)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1099)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:230)
04:14:49    at ParkLoops.main(ParkLoops.java:124)
04:14:49    at java.base@21.0.3-internal/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
04:14:49    at java.base@21.0.3-internal/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 java.base@21.0.3-internal/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 java.base@21.0.3-internal/jdk.internal.misc.Unsafe.park(Native Method)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)
04:14:49    at ParkLoops$Parker.run(ParkLoops.java:77)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.FutureTask.run(FutureTask.java:317)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
04:14:49    at java.base@21.0.3-internal/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 java.base@21.0.3-internal/java.lang.Object.waitImpl(Native Method)
04:14:49    at java.base@21.0.3-internal/java.lang.Object.wait(Object.java:255)
04:14:49    at java.base@21.0.3-internal/java.lang.Object.wait(Object.java:221)
04:14:49    at java.base@21.0.3-internal/java.util.TimerThread.mainLoop(Timer.java:602)
04:14:49    at java.base@21.0.3-internal/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 java.base@21.0.3-internal/openj9.internal.tools.attach.target.DiagnosticUtils.dumpAllThreadsImpl(Native Method)
04:14:49    at java.base@21.0.3-internal/openj9.internal.tools.attach.target.DiagnosticUtils.getThreadInfo(DiagnosticUtils.java:249)
04:14:49    at java.base@21.0.3-internal/openj9.internal.tools.attach.target.DiagnosticUtils.executeDiagnosticCommand(DiagnosticUtils.java:185)
04:14:49    at java.base@21.0.3-internal/openj9.internal.tools.attach.target.Attachment.doCommand(Attachment.java:248)
04:14:49    at java.base@21.0.3-internal/openj9.internal.tools.attach.target.Attachment.run(Attachment.java:159)
04:14:49  
04:14:49  
04:14:49  --- Timeout information end.
pshipton commented 8 months ago

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

pshipton commented 8 months ago

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

pshipton commented 8 months ago

@TobiAjila This started failing with some frequency last week.

pshipton commented 8 months ago

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/

tajila commented 8 months ago

It looks like the test has completed but the test harness code is still running

tajila commented 8 months ago

It looks similar to https://github.com/eclipse-openj9/openj9/issues/9651 excpet that this test doesn't appear to do excessive GC

tajila commented 8 months ago

NVM, here is the issue

04:14:49  "AgentVMThread" prio=5 Id=363 WAITING
04:14:49    at java.base@21.0.3-internal/jdk.internal.misc.Unsafe.park(Native Method)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.locks.LockSupport.park(LockSupport.java:221)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:754)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1099)
04:14:49    at java.base@21.0.3-internal/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:230)
04:14:49    at ParkLoops.main(ParkLoops.java:124)
04:14:49    at java.base@21.0.3-internal/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
04:14:49    at java.base@21.0.3-internal/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 java.base@21.0.3-internal/java.lang.Thread.run(Thread.java:1595)
tajila commented 8 months ago

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.

tajila commented 8 months ago

-Xint https://openj9-jenkins.osuosl.org/job/Grinder/3300/ (0/30 failed) -Xjit https://openj9-jenkins.osuosl.org/job/Grinder/3301/ (4/30 failed)

tajila commented 8 months ago

My guess is that a call to unpark is being missed, perhaps being optimized out?

tajila commented 8 months ago

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

tajila commented 8 months ago

60 runs with jit exclude on ParkLoops https://openj9-jenkins.osuosl.org/job/Grinder/3303/ (two failures)

tajila commented 8 months ago

60 runs with OSR turned off https://openj9-jenkins.osuosl.org/job/Grinder/3304/ (3 failures)

tajila commented 8 months ago

80 runs excluding LockSupport compilation https://openj9-jenkins.osuosl.org/job/Grinder/3315/ no failures

tajila commented 8 months ago

More runs with -Xjit:exclude={ParkLoops.,java/util/concurrent/locks/LockSupport.} https://openj9-jenkins.osuosl.org/job/Grinder/3316/ (140 runs - 11 failures)

tajila commented 8 months ago

Retrying Xint https://openj9-jenkins.osuosl.org/job/Grinder/3317/ (200 runs) no failures

pshipton commented 8 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_x86-64_windows_Nightly_testList_2/158 - timeout

pshipton commented 8 months ago

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

pshipton commented 8 months ago

This continues to occur, but I won't keep reporting them all.

hzongaro commented 8 months ago

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.

hzongaro commented 7 months ago

It seems that, at the minimum, the following two methods must be compiled to reproduce the failure:

I have managed to reproduce the failure with those rather trivial methods compiled with optLevel=noopt — internal grinder run 38272 (3/40 failures)

hzongaro commented 7 months ago

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.

hzongaro commented 7 months ago

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.

pshipton commented 7 months ago

Right, I haven't seen one of these failures in a while.

pshipton commented 7 months ago

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.