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.

Sign up for GitHub

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

Jump to bottom

jdk19 OpenJDK java/lang/Thread/virtual/ActiviateSpareCarrier.java timeout #16198

Closed
pshipton opened this issue Oct 26, 2022 · 3 comments · Fixed by #16324
Closed

jdk19 OpenJDK java/lang/Thread/virtual/ActiviateSpareCarrier.java timeout #16198

pshipton opened this issue Oct 26, 2022 · 3 comments · Fixed by #16324
Assignees
@fengxue-IS
Labels
comp:vm jdk19 project:loom Used to track Project Loom related work test failure
Milestone
Java 19 0.37

Comments

@pshipton
Copy link
Member

pshipton commented Oct 26, 2022 •
edited
Loading

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_aarch64_linux_Nightly/36
java/lang/Thread/virtual/ActiviateSpareCarrier.java

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk19_j9_sanity.openjdk_aarch64_linux_Nightly/36/openjdk_test_output.tar.gz

21:15:33  ACTION: main -- Error. Program `/home/jenkins/workspace/Test_openjdk19_j9_sanity.openjdk_aarch64_linux_Nightly/openjdkbinary/j2sdk-image/bin/java' timed out (timeout set to 960000ms, elapsed time including timeout handling was 963300ms).
21:15:33  REASON: User specified action: run main/othervm -Djdk.virtualThreadScheduler.parallelism=1 -Djdk.virtualThreadScheduler.maxPoolSize=2 ActiviateSpareCarrier 100 
21:15:33  TIME:   963.302 seconds
21:15:33  messages:
21:15:33  command: main -Djdk.virtualThreadScheduler.parallelism=1 -Djdk.virtualThreadScheduler.maxPoolSize=2 ActiviateSpareCarrier 100
21:15:33  reason: User specified action: run main/othervm -Djdk.virtualThreadScheduler.parallelism=1 -Djdk.virtualThreadScheduler.maxPoolSize=2 ActiviateSpareCarrier 100 
21:15:33  Mode: othervm [/othervm specified]
21:15:33  Timeout information:
21:15:33  Running jcmd on process 3988527
21:15:33  Dump written to /home/jenkins/workspace/Test_openjdk19_j9_sanity.openjdk_aarch64_linux_Nightly/aqa-tests/TKG/output_16667454137865/jdk_lang_0/work/scratch/1/core.20221025.211529.3988527.0001.dmp
21:15:33  Dump written to /home/jenkins/workspace/Test_openjdk19_j9_sanity.openjdk_aarch64_linux_Nightly/aqa-tests/TKG/output_16667454137865/jdk_lang_0/work/scratch/1/javacore.20221025.211530.3988527.0002.txt
21:15:33  Running jstack on process 3988527
21:15:33  2022-10-25T21:15:30.956324982
21:15:33  Virtual machine: 3988527 JVM information:
21:15:33  JRE 19 Linux aarch64-64-Bit Compressed References 20221025_102 (JIT enabled, AOT enabled)
21:15:33  OpenJ9   - 53c0b4dbbab
21:15:33  OMR      - f6bafc5fa7b
21:15:33  JCL      - ac249fd84ac based on jdk-19.0.1+10
21:15:33  
21:15:33  "main" prio=5 Id=2 WAITING
21:15:33  	at java.base@19.0.1-internal/java.lang.Object.wait(Native Method)
21:15:33  	at java.base@19.0.1-internal/java.lang.Object.wait(Object.java:219)
21:15:33  	at java.base@19.0.1-internal/java.lang.Thread.join(Thread.java:2144)
21:15:33  	at java.base@19.0.1-internal/java.lang.Thread.join(Thread.java:2220)
21:15:33  	at app//com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:74)
21:15:33  
21:15:33  "JIT Compilation Thread-000" prio=10 Id=4 RUNNABLE
21:15:33  
21:15:33  "JIT Compilation Thread-001 Suspended" prio=10 Id=5 RUNNABLE
21:15:33  
21:15:33  "JIT Compilation Thread-002 Suspended" prio=10 Id=6 RUNNABLE
21:15:33  
21:15:33  "JIT Compilation Thread-003 Suspended" prio=10 Id=7 RUNNABLE
21:15:33  
21:15:33  "JIT Compilation Thread-004 Suspended" prio=10 Id=8 RUNNABLE
21:15:33  
21:15:33  "JIT Compilation Thread-005 Suspended" prio=10 Id=9 RUNNABLE
21:15:33  
21:15:33  "JIT Compilation Thread-006 Suspended" prio=10 Id=10 RUNNABLE
21:15:33  
21:15:33  "JIT Diagnostic Compilation Thread-007 Suspended" prio=10 Id=11 RUNNABLE
21:15:33  
21:15:33  "JIT-SamplerThread" prio=10 Id=12 TIMED_WAITING
21:15:33  
21:15:33  "IProfiler" prio=5 Id=13 RUNNABLE
21:15:33  
21:15:33  "Common-Cleaner" prio=8 Id=3 TIMED_WAITING
21:15:33  	at java.base@19.0.1-internal/java.lang.Object.wait(Native Method)
21:15:33  	at java.base@19.0.1-internal/java.lang.Object.wait(Object.java:219)
21:15:33  	at java.base@19.0.1-internal/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:137)
21:15:33  	at java.base@19.0.1-internal/jdk.internal.ref.CleanerImpl.run(CleanerImpl.java:140)
21:15:33  	at java.base@19.0.1-internal/java.lang.Thread.run(Thread.java:1573)
21:15:33  	at java.base@19.0.1-internal/jdk.internal.misc.InnocuousThread.run(InnocuousThread.java:186)
21:15:33  
21:15:33  "Concurrent Mark Helper" prio=1 Id=14 RUNNABLE
21:15:33  
21:15:33  "GC Worker" prio=5 Id=15 RUNNABLE
21:15:33  
21:15:33  "GC Worker" prio=5 Id=16 RUNNABLE
21:15:33  
21:15:33  "GC Worker" prio=5 Id=17 RUNNABLE
21:15:33  
21:15:33  "GC Worker" prio=5 Id=18 RUNNABLE
21:15:33  
21:15:33  "GC Worker" prio=5 Id=19 RUNNABLE
21:15:33  
21:15:33  "GC Worker" prio=5 Id=20 RUNNABLE
21:15:33  
21:15:33  "GC Worker" prio=5 Id=21 RUNNABLE
21:15:33  
21:15:33  "Finalizer thread" prio=5 Id=24 RUNNABLE
21:15:33  
21:15:33  "Attach API wait loop" prio=10 Id=25 RUNNABLE
21:15:33  	at java.base@19.0.1-internal/openj9.internal.tools.attach.target.IPC.waitSemaphore(Native Method)
21:15:33  	at java.base@19.0.1-internal/openj9.internal.tools.attach.target.CommonDirectory.waitSemaphore(CommonDirectory.java:264)
21:15:33  	at java.base@19.0.1-internal/openj9.internal.tools.attach.target.WaitLoop.waitForNotification(WaitLoop.java:66)
21:15:33  	at java.base@19.0.1-internal/openj9.internal.tools.attach.target.WaitLoop.run(WaitLoop.java:157)
21:15:33  
21:15:33  "MainThread" prio=5 Id=27 WAITING
21:15:33  	at java.base@19.0.1-internal/jdk.internal.misc.Unsafe.park(Native Method)
21:15:33  	at java.base@19.0.1-internal/java.util.concurrent.locks.LockSupport.park(LockSupport.java:221)
21:15:33  	at java.base@19.0.1-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:715)
21:15:33  	at java.base@19.0.1-internal/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1047)
21:15:33  	at java.base@19.0.1-internal/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:230)
21:15:33  	at java.base@19.0.1-internal/java.lang.VirtualThread.joinNanos(VirtualThread.java:749)
21:15:33  	at java.base@19.0.1-internal/java.lang.Thread.join(Thread.java:2127)
21:15:33  	at java.base@19.0.1-internal/java.lang.Thread.join(Thread.java:2220)
21:15:33  	at app//ActiviateSpareCarrier.joinThread(ActiviateSpareCarrier.java:126)
21:15:33  	at app//ActiviateSpareCarrier.startAndJoinVirtualThread(ActiviateSpareCarrier.java:112)
21:15:33  	at app//ActiviateSpareCarrier.test(ActiviateSpareCarrier.java:91)
21:15:33  	at app//ActiviateSpareCarrier.main(ActiviateSpareCarrier.java:57)
21:15:33  	at java.base@19.0.1-internal/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
21:15:33  	at java.base@19.0.1-internal/java.lang.reflect.Method.invoke(Method.java:578)
21:15:33  	at app//com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
21:15:33  	at java.base@19.0.1-internal/java.lang.Thread.run(Thread.java:1573)
21:15:33  
21:15:33  "ForkJoinPool-1-worker-2" prio=5 Id=30 WAITING
21:15:33  	at java.base@19.0.1-internal/jdk.internal.misc.Unsafe.park(Native Method)
21:15:33  	at java.base@19.0.1-internal/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)
21:15:33  	at java.base@19.0.1-internal/java.util.concurrent.ForkJoinPool.awaitWork(ForkJoinPool.java:1890)
21:15:33  	at java.base@19.0.1-internal/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1807)
21:15:33  	at java.base@19.0.1-internal/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:177)
21:15:33  
21:15:33  "file lock watchdog" prio=10 Id=33 TIMED_WAITING
21:15:33  	at java.base@19.0.1-internal/java.lang.Object.wait(Native Method)
21:15:33  	at java.base@19.0.1-internal/java.lang.Object.wait(Object.java:219)
21:15:33  	at java.base@19.0.1-internal/java.util.TimerThread.mainLoop(Timer.java:563)
21:15:33  	at java.base@19.0.1-internal/java.util.TimerThread.run(Timer.java:516)
21:15:33  
21:15:33  "Attachment portNumber: 42509" prio=10 Id=35 RUNNABLE
21:15:33  	at java.base@19.0.1-internal/openj9.internal.tools.attach.target.DiagnosticUtils.dumpAllThreadsImpl(Native Method)
21:15:33  	at java.base@19.0.1-internal/openj9.internal.tools.attach.target.DiagnosticUtils.getThreadInfo(DiagnosticUtils.java:245)
21:15:33  	at java.base@19.0.1-internal/openj9.internal.tools.attach.target.DiagnosticUtils.executeDiagnosticCommand(DiagnosticUtils.java:181)
21:15:33  	at java.base@19.0.1-internal/openj9.internal.tools.attach.target.Attachment.doCommand(Attachment.java:248)
21:15:33  	at java.base@19.0.1-internal/openj9.internal.tools.attach.target.Attachment.run(Attachment.java:159)
21:15:33  
21:15:33  
21:15:33  --- Timeout information end.
21:15:33  elapsed time (seconds): 963.302
21:15:33  configuration:
21:15:33  STDOUT:
21:15:33  ---- 0 ----
21:15:33  starting waiter thread #28
21:15:33  VirtualThread[#28]/runnable@ForkJoinPool-1-worker-1
21:15:33  starting #31
21:15:33  Waiting for #31 to terminate
21:15:33  #31 did not terminate quickly, continue to wait...
21:15:33  ForkJoinWorkerThreads:
21:15:33      Thread[#29,ForkJoinPool-1-worker-1,5,CarrierThreads]
21:15:33        java.base/jdk.internal.vm.Continuation.enterImpl(Native Method)
21:15:33        java.base/jdk.internal.vm.Continuation.run(Continuation.java:199)
21:15:33        java.base/java.lang.VirtualThread.runContinuation(VirtualThread.java:218)
21:15:33        java.base/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1423)
21:15:33        java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:387)
21:15:33        java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1311)
21:15:33        java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1840)
21:15:33        java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1806)
21:15:33        java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:177)
21:15:33      Thread[#30,ForkJoinPool-1-worker-2,5,CarrierThreads]
21:15:33        java.base/jdk.internal.misc.Unsafe.park(Native Method)
21:15:33        java.base/java.util.concurrent.locks.LockSupport.park(LockSupport.java:371)
21:15:33        java.base/java.util.concurrent.ForkJoinPool.awaitWork(ForkJoinPool.java:1890)
21:15:33        java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1807)
21:15:33        java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:177)
21:15:33  Timeout refired 960 times
21:15:33  STDERR:
21:15:33  JVMDUMP034I User requested System dump using '/home/jenkins/workspace/Test_openjdk19_j9_sanity.openjdk_aarch64_linux_Nightly/aqa-tests/TKG/output_16667454137865/jdk_lang_0/work/scratch/1/core.20221025.211529.3988527.0001.dmp' through com.ibm.jvm.Dump.systemDumpToFile
21:15:33  JVMDUMP010I System dump written to /home/jenkins/workspace/Test_openjdk19_j9_sanity.openjdk_aarch64_linux_Nightly/aqa-tests/TKG/output_16667454137865/jdk_lang_0/work/scratch/1/core.20221025.211529.3988527.0001.dmp
21:15:33  JVMDUMP034I User requested Java dump using '/home/jenkins/workspace/Test_openjdk19_j9_sanity.openjdk_aarch64_linux_Nightly/aqa-tests/TKG/output_16667454137865/jdk_lang_0/work/scratch/1/javacore.20221025.211530.3988527.0002.txt' through com.ibm.jvm.Dump.javaDumpToFile
21:15:33  JVMDUMP010I Java dump written to /home/jenkins/workspace/Test_openjdk19_j9_sanity.openjdk_aarch64_linux_Nightly/aqa-tests/TKG/output_16667454137865/jdk_lang_0/work/scratch/1/javacore.20221025.211530.3988527.0002.txt

Failed on amac as well although jstack couldn't connect to get the stacks. I suspect it's going to fail on all platforms.
https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_sanity.openjdk_aarch64_mac_Nightly/38/

I expect this is related to ibmruntimes/openj9-openjdk-jdk19#40
@pshipton pshipton added this to the Java 19 milestone Oct 26, 2022
@pshipton
Copy link
Member Author

@tajila @fengxue-IS fyi

@pshipton pshipton changed the title jdk19 OpenJDK java/lang/Thread/virtual/ActiviateSpareCarrier.java jdk19 OpenJDK java/lang/Thread/virtual/ActiviateSpareCarrier.java timeout Oct 26, 2022
@fengxue-IS fengxue-IS mentioned this issue Oct 26, 2022
Merged
@fengxue-IS
Copy link
Contributor

It is a new test added to the JDK19 repo in 19.0.1 which has not been test before.
I've created a PR to exclude this test while this failure is being triaged

@fengxue-IS
Copy link
Contributor

fengxue-IS commented Nov 1, 2022 •
edited
Loading

Test failure due the behaviour of commandline option used by test.

-Djdk.virtualThreadScheduler.parallelism=1 -Djdk.virtualThreadScheduler.maxPoolSize=2

Test passed with -Djdk.virtualThreadScheduler.parallelism=2, so seems like OpenJ9 doesn't activate the spare carrier thread correctly when initial carrier is waiting. The code on activation is part of ForkJoinPool and Blockers which is part of the OpenJDK JCL which make this a bit strange.

Will add more debug output to the build to see if the tryCompensate function used to activate spare thread is correctly triggered.

@tajila tajila added the project:loom Used to track Project Loom related work label Nov 3, 2022
@fengxue-IS fengxue-IS mentioned this issue Nov 14, 2022
Merged
@tajila tajila mentioned this issue Nov 18, 2022
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@fengxue-IS fengxue-IS

Labels
comp:vm jdk19 project:loom Used to track Project Loom related work test failure
Projects
None yet
Milestone
Java 19 0.37
Development

Successfully merging a pull request may close this issue.

Update Object.wait to use Blocker.begin/end for Java 19+ fengxue-IS/openj9
3 participants
@fengxue-IS @tajila @pshipton