Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

OpenJDK java/util/concurrent/forkjoin/Starvation timeout #19932

Open
pshipton opened this issue Jul 30, 2024 · 9 comments
Open

OpenJDK java/util/concurrent/forkjoin/Starvation timeout #19932

pshipton opened this issue Jul 30, 2024 · 9 comments
Assignees

Comments

@pshipton
Copy link
Member

pshipton commented Jul 30, 2024

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
Copy link
Member Author

pshipton commented Jul 30, 2024

May just be due to slow zlinux machines?

@pshipton
Copy link
Member Author

pshipton commented Aug 1, 2024

@TobiAjila @fengxue-IS fyi

@tajila
Copy link
Contributor

tajila commented Aug 1, 2024

@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 fengxue-IS self-assigned this Aug 1, 2024
@fengxue-IS
Copy link
Contributor

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

@fengxue-IS
Copy link
Contributor

fengxue-IS commented Aug 7, 2024

25x Grinder passed on entire jdk_util_0 suite.

@pshipton pshipton removed this from the Java 23 (0.47) milestone Aug 12, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants