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 java/util/concurrent/forkjoin/Starvation timeout #19932

Open pshipton opened 2 months ago

pshipton commented 2 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk23_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/35 - rh8-390-2 jdk_util_0 java/util/concurrent/forkjoin/Starvation.java

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk23_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/35/openjdk_test_output.tar.gz

05:27:57  Timeout signalled after 960 seconds
05:27:57  Timeout information:
05:27:57  Running jcmd on process 2327536
05:27:57  Dump written to /home/jenkins/workspace/Test_openjdk23_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/aqa-tests/TKG/output_17223275793852/jdk_util_0/work/scratch/0/core.20240730.052612.2327536.0001.dmp
05:27:57  Dump written to /home/jenkins/workspace/Test_openjdk23_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/aqa-tests/TKG/output_17223275793852/jdk_util_0/work/scratch/0/javacore.20240730.052744.2327536.0002.txt
05:27:57  Running jstack on process 2327536
05:27:57  2024-07-30T05:27:44.448756292
05:27:57  Virtual machine: 2327536 JVM information:
05:27:57  JRE 23 Linux s390x-64-Bit Compressed References 20240729_36 (JIT enabled, AOT enabled)
05:27:57  OpenJ9   - 0362cb326d8
05:27:57  OMR      - d18121d17c5
05:27:57  JCL      - e729061f0c8 based on jdk-23+33
05:27:57  
05:27:57  "main" prio=5 Id=2 WAITING
05:27:57    at java.base@23-internal/java.lang.Object.waitImpl(Native Method)
05:27:57    at java.base@23-internal/java.lang.Object.wait(Object.java:254)
05:27:57    at java.base@23-internal/java.lang.Object.wait(Object.java:221)
05:27:57    at java.base@23-internal/java.lang.Thread.join(Thread.java:2088)
05:27:57    at java.base@23-internal/java.lang.Thread.join(Thread.java:2164)
05:27:57    at app//com.sun.javatest.regtest.agent.MainActionHelper.runClass(MainActionHelper.java:219)
05:27:57    at app//com.sun.javatest.regtest.agent.AgentServer.doMain(AgentServer.java:317)
05:27:57    at app//com.sun.javatest.regtest.agent.AgentServer.run(AgentServer.java:242)
05:27:57    at app//com.sun.javatest.regtest.agent.AgentServer.main(AgentServer.java:71)
05:27:57  
05:27:57  "JIT Compilation Thread-000" prio=10 Id=4 RUNNABLE
05:27:57  
05:27:57  "JIT Compilation Thread-001 Suspended" prio=10 Id=5 RUNNABLE
05:27:57  
05:27:57  "JIT Compilation Thread-002 Suspended" prio=10 Id=6 RUNNABLE
05:27:57  
05:27:57  "JIT Compilation Thread-003 Suspended" prio=10 Id=7 RUNNABLE
05:27:57  
05:27:57  "JIT Compilation Thread-004 Suspended" prio=10 Id=8 RUNNABLE
05:27:57  
05:27:57  "JIT Compilation Thread-005 Suspended" prio=10 Id=9 RUNNABLE
05:27:57  
05:27:57  "JIT Compilation Thread-006 Suspended" prio=10 Id=10 RUNNABLE
05:27:57  
05:27:57  "JIT Diagnostic Compilation Thread-007 Suspended" prio=10 Id=11 RUNNABLE
05:27:57  
05:27:57  "JIT-SamplerThread" prio=10 Id=12 TIMED_WAITING
05:27:57  
05:27:57  "IProfiler" prio=5 Id=13 RUNNABLE
05:27:57  
05:27:57  "Common-Cleaner" prio=8 Id=3 TIMED_WAITING
05:27:57    at java.base@23-internal/java.lang.Object.waitImpl(Native Method)
05:27:57    at java.base@23-internal/java.lang.Object.wait(Object.java:254)
05:27:57    at java.base@23-internal/java.lang.Object.wait(Object.java:221)
05:27:57    at java.base@23-internal/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:140)
05:27:57    at java.base@23-internal/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:140)
05:27:57    at java.base@23-internal/java.lang.Thread.run(Thread.java:1587)
05:27:57    at java.base@23-internal/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)
05:27:57  
05:27:57  "Concurrent Mark Helper" prio=1 Id=14 RUNNABLE
05:27:57  
05:27:57  "GC Worker" prio=5 Id=15 RUNNABLE
05:27:57  
05:27:57  "GC Worker" prio=5 Id=16 RUNNABLE
05:27:57  
05:27:57  "GC Worker" prio=5 Id=17 RUNNABLE
05:27:57  
05:27:57  "Finalizer thread" prio=5 Id=18 RUNNABLE
05:27:57  
05:27:57  "Attach API update file access time" prio=5 Id=21 TIMED_WAITING
05:27:57    at java.base@23-internal/java.lang.Thread.sleepImpl(Native Method)
05:27:57    at java.base@23-internal/java.lang.Thread.sleepNanos(Thread.java:503)
05:27:57    at java.base@23-internal/java.lang.Thread.sleep(Thread.java:534)
05:27:57    at java.base@23-internal/openj9.internal.tools.attach.target.AttachHandler$1.run(AttachHandler.java:348)
05:27:57  
05:27:57  "Attach API wait loop" prio=10 Id=22 RUNNABLE
05:27:57    at java.base@23-internal/openj9.internal.tools.attach.target.IPC.waitSemaphore(Native Method)
05:27:57    at java.base@23-internal/openj9.internal.tools.attach.target.CommonDirectory.waitSemaphore(CommonDirectory.java:264)
05:27:57    at java.base@23-internal/openj9.internal.tools.attach.target.WaitLoop.waitForNotification(WaitLoop.java:66)
05:27:57    at java.base@23-internal/openj9.internal.tools.attach.target.WaitLoop.run(WaitLoop.java:157)
05:27:57  
05:27:57  "pool-1-thread-1" prio=5 Id=23 TIMED_WAITING
05:27:57    at java.base@23-internal/jdk.internal.misc.Unsafe.park(Native Method)
05:27:57    at java.base@23-internal/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:269)
05:27:57    at java.base@23-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1763)
05:27:57    at java.base@23-internal/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1182)
05:27:57    at java.base@23-internal/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
05:27:57    at java.base@23-internal/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1070)
05:27:57    at java.base@23-internal/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
05:27:57    at java.base@23-internal/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
05:27:57    at java.base@23-internal/java.lang.Thread.run(Thread.java:1587)
05:27:57  
05:27:57  "ClassByNameCache Reaper" prio=5 Id=44 WAITING
05:27:57    at java.base@23-internal/java.lang.Object.waitImpl(Native Method)
05:27:57    at java.base@23-internal/java.lang.Object.wait(Object.java:254)
05:27:57    at java.base@23-internal/java.lang.Object.wait(Object.java:221)
05:27:57    at java.base@23-internal/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:140)
05:27:57    at java.base@23-internal/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:112)
05:27:57    at java.base@23-internal/java.io.ClassByNameCache$Reaper.run(ClassByNameCache.java:232)
05:27:57    at java.base@23-internal/java.lang.Thread.run(Thread.java:1587)
05:27:57  
05:27:57  "VirtualThread-unparker" prio=5 Id=643 WAITING
05:27:57    at java.base@23-internal/jdk.internal.misc.Unsafe.park(Native Method)
05:27:57    at java.base@23-internal/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)
05:27:57    at java.base@23-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(AbstractQueuedSynchronizer.java:519)
05:27:57    at java.base@23-internal/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:4021)
05:27:57    at java.base@23-internal/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3967)
05:27:57    at java.base@23-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1712)
05:27:57    at java.base@23-internal/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1170)
05:27:57    at java.base@23-internal/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
05:27:57    at java.base@23-internal/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1070)
05:27:57    at java.base@23-internal/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
05:27:57    at java.base@23-internal/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
05:27:57    at java.base@23-internal/java.lang.Thread.run(Thread.java:1587)
05:27:57    at java.base@23-internal/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)
05:27:57  
05:27:57  "AgentVMThread" prio=5 Id=969 WAITING
05:27:57    at java.base@23-internal/jdk.internal.misc.Unsafe.park(Native Method)
05:27:57    at java.base@23-internal/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)
05:27:57    at java.base@23-internal/java.util.concurrent.ForkJoinTask.awaitDone(ForkJoinTask.java:441)
05:27:57    at java.base@23-internal/java.util.concurrent.ForkJoinTask.awaitDone(ForkJoinTask.java:496)
05:27:57    at java.base@23-internal/java.util.concurrent.ForkJoinTask.get(ForkJoinTask.java:1003)
05:27:57    at Starvation.main(Starvation.java:50)
05:27:57    at java.base@23-internal/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
05:27:57    at java.base@23-internal/java.lang.reflect.Method.invoke(Method.java:586)
05:27:57    at app//com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:333)
05:27:57    at java.base@23-internal/java.lang.Thread.run(Thread.java:1587)
05:27:57  
05:27:57  "ForkJoinPool-50-worker-1" prio=5 Id=970 RUNNABLE
05:27:57    at Starvation$AwaitCount.call(Starvation.java:42)
05:27:57    at Starvation$AwaitCount.call(Starvation.java:38)
05:27:57    at java.base@23-internal/java.util.concurrent.ForkJoinTask$AdaptedInterruptibleCallable.compute(ForkJoinTask.java:1689)
05:27:57    at java.base@23-internal/java.util.concurrent.ForkJoinTask$InterruptibleTask.exec(ForkJoinTask.java:1641)
05:27:57    at java.base@23-internal/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:507)
05:27:57    at java.base@23-internal/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1458)
05:27:57    at java.base@23-internal/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:2034)
05:27:57    at java.base@23-internal/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:189)
05:27:57  
05:27:57  "ForkJoinPool-50-worker-2" prio=5 Id=971 RUNNABLE
05:27:57    at java.base@23-internal/jdk.internal.misc.Unsafe.park(Native Method)
05:27:57    at java.base@23-internal/java.util.concurrent.ForkJoinPool.awaitWork(ForkJoinPool.java:2135)
05:27:57    at java.base@23-internal/java.util.concurrent.ForkJoinPool.deactivate(ForkJoinPool.java:2099)
05:27:57    at java.base@23-internal/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:2043)
05:27:57    at java.base@23-internal/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:189)
05:27:57  
05:27:57  "file lock watchdog" prio=10 Id=973 TIMED_WAITING
05:27:57    at java.base@23-internal/java.lang.Object.waitImpl(Native Method)
05:27:57    at java.base@23-internal/java.lang.Object.wait(Object.java:254)
05:27:57    at java.base@23-internal/java.lang.Object.wait(Object.java:221)
05:27:57    at java.base@23-internal/java.util.TimerThread.mainLoop(Timer.java:608)
05:27:57    at java.base@23-internal/java.util.TimerThread.run(Timer.java:549)
05:27:57  
05:27:57  "Attachment portNumber: 44529" prio=10 Id=975 RUNNABLE
05:27:57    at java.base@23-internal/openj9.internal.tools.attach.target.DiagnosticUtils.dumpAllThreadsImpl(Native Method)
05:27:57    at java.base@23-internal/openj9.internal.tools.attach.target.DiagnosticUtils.getThreadInfo(DiagnosticUtils.java:249)
05:27:57    at java.base@23-internal/openj9.internal.tools.attach.target.DiagnosticUtils.executeDiagnosticCommand(DiagnosticUtils.java:185)
05:27:57    at java.base@23-internal/openj9.internal.tools.attach.target.Attachment.doCommand(Attachment.java:252)
05:27:57    at java.base@23-internal/openj9.internal.tools.attach.target.Attachment.run(Attachment.java:162)
05:27:57  
05:27:57  
05:27:57  --- Timeout information end.
pshipton commented 2 months ago

May just be due to slow zlinux machines?

pshipton commented 2 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk23_j9_sanity.openjdk_s390x_linux_Nightly_testList_0/37/ - rh8-390-1

pshipton commented 2 months ago

@TobiAjila @fengxue-IS fyi

tajila commented 2 months ago

@fengxue-IS Please take a look.

One thing to determine is if this test consistently passed before. Im not familiar with it so it could be new.

fengxue-IS commented 2 months ago

100x grinder passed, will try running test as a suite to see if that reproduces the problem.

fengxue-IS commented 2 months ago

25x Grinder passed on entire jdk_util_0 suite.

pshipton commented 2 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk23_j9_sanity.openjdk_s390x_linux_OpenJDK23_testList_0/7/

pshipton commented 1 month ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk23_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/62

pshipton commented 1 month ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk23_j9_sanity.openjdk_s390x_linux_Nightly_testList_0/76 https://openj9-jenkins.osuosl.org/job/Test_openjdk23_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/76

https://openj9-jenkins.osuosl.org/job/Test_openjdk23_j9_sanity.openjdk_s390x_linux_Nightly_testList_0/78