JDK-8286352 : java/util/concurrent/forkjoin/AsyncShutdownNow.java timed out
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.util.concurrent
  • Affected Version: 19,20,21
  • Priority: P3
  • Status: Closed
  • Resolution: Duplicate
  • OS: windows
  • CPU: x86_64
  • Submitted: 2022-05-07
  • Updated: 2024-06-25
  • Resolved: 2024-05-02
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 22
22Resolved
Related Reports
Duplicate :  
JDK-8288899 - java/util/concurrent/ExecutorService/CloseTest.java failed with "InterruptedException: sleep interrupted"
Relates :  
JDK-8334993 - Test java/util/concurrent/forkjoin/AsyncShutdownNow.java timed out again
Relates :  
JDK-8296405 - java/util/concurrent/forkjoin/AsyncShutdownNow.java is too slow
Relates :  
JDK-8288899 - java/util/concurrent/ExecutorService/CloseTest.java failed with "InterruptedException: sleep interrupted"
Sub Tasks
JDK-8298214 :  
ProblemList java/util/concurrent/forkjoin/AsyncShutdownNow.java - Resolved
Description
The following test timed out in the jdk-19-loomvt CI:

java/util/concurrent/forkjoin/AsyncShutdownNow.java

Here's a log file snippet:

#section:testng
----------messages:(8/235)----------
command: testng AsyncShutdownNow
reason: User specified action: run testng AsyncShutdownNow 
Mode: agentvm
Agent id: 8
Timeout refired 480 times
Timeout information:
--- Timeout information end.
elapsed time (seconds): 495.342
----------configuration:(14/1314)*----------
Boot Layer
  class path: C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\6.1\\1\\bundles\\jtreg-6.1+1.zip\\jtreg\\lib\\javatest.jar 
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\6.1\\1\\bundles\\jtreg-6.1+1.zip\\jtreg\\lib\\jtreg.jar 
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\6.1\\1\\bundles\\jtreg-6.1+1.zip\\jtreg\\lib\\junit.jar 
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\6.1\\1\\bundles\\jtreg-6.1+1.zip\\jtreg\\lib\\hamcrest.jar 
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\6.1\\1\\bundles\\jtreg-6.1+1.zip\\jtreg\\lib\\testng.jar 
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\6.1\\1\\bundles\\jtreg-6.1+1.zip\\jtreg\\lib\\jcommander.jar 
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\6.1\\1\\bundles\\jtreg-6.1+1.zip\\jtreg\\lib\\guice.jar 
  patch:      java.base T:\\testoutput\\test-support\\jtreg_open_test_jdk_tier1_part2\\patches\\java.base

Test Layer
  class path: T:\\testoutput\\test-support\\jtreg_open_test_jdk_tier1_part2\\classes\\3\\java\\util\\concurrent\\forkjoin\\AsyncShutdownNow.d
              C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-19-loomvt+1-56\\src.full\\open\\test\\jdk\\java\\util\\concurrent\\forkjoin

----------rerun:(33/4697)*----------

<snip>

result: Error. Agent error: java.lang.Exception: Agent 8 timed out with a timeout of 480 seconds; check console log for any additional details

Starting this bug at P2 since this is a Tier1 failure.
Comments
This is likely to be fixed in 22 given https://bugs.openjdk.org/browse/JDK-8288899
01-05-2024
Here's a log file snippet for the jdk-22+14-969-tier1 sighting: java/util/concurrent/forkjoin/AsyncShutdownNow.java #section:testng ----------messages:(10/313)---------- command: testng AsyncShutdownNow reason: User specified action: run testng AsyncShutdownNow started: Thu Aug 31 19:43:28 GMT 2023 Mode: agentvm Agent id: 8 Timeout signalled after 480 seconds Timeout information: --- Timeout information end. finished: Thu Aug 31 19:54:03 GMT 2023 elapsed time (seconds): 634.51 ----------configuration:(12/1554)---------- <snip> ----------System.out:(5/655)---------- testFutureGet: java.util.concurrent.ForkJoinPool@7611c458[Running, parallelism = 8, size = 0, active = 0, running = 0, steals = 0, tasks = 0, submissions = 0] test AsyncShutdownNow.testFutureGet(java.util.concurrent.ForkJoinPool@7611c458): success testFutureGet: java.util.concurrent.ForkJoinPool@206ad0d6[Running, parallelism = 1, size = 0, active = 0, running = 0, steals = 0, tasks = 0, submissions = 0] test AsyncShutdownNow.testFutureGet(java.util.concurrent.ForkJoinPool@206ad0d6): success testInvokeAll: java.util.concurrent.ForkJoinPool@4ff2fa30[Running, parallelism = 8, size = 0, active = 0, running = 0, steals = 0, tasks = 0, submissions = 0] result: Error. Agent error: java.lang.Exception: Agent 8 timed out with a timeout of 480 seconds; check console log for any additional details test result: Error. Agent error: java.lang.Exception: Agent 8 timed out with a timeout of 480 seconds; check console log for any additional details
31-08-2023
The sighting in jdk-21+16-1321 is testInvokeAll on macosx-aarch64. This test is currently excluded on Linux and Windows, but still runs on macOS for some reason. Doug Lea has a big update to ForkJoinPool coming that completely re-works the shutdown and will allow the test to run on all platforms again.
30-03-2023
Here's a log file snippet from the jdk-21+16-1321-tier1 sighting: java/util/concurrent/forkjoin/AsyncShutdownNow.java #section:testng ----------messages:(10/303)---------- command: testng AsyncShutdownNow reason: User specified action: run testng AsyncShutdownNow started: Wed Mar 29 17:29:21 GMT 2023 Mode: agentvm Agent id: 6 Timeout refired 480 times Timeout information: --- Timeout information end. finished: Wed Mar 29 17:37:53 GMT 2023 elapsed time (seconds): 511.79 ----------configuration:(12/1553)---------- Boot Layer class path: /System/Volumes/Data/mesos/work_dir/jib-master/install/jtreg/7.1.1/1/bundles/jtreg-7.1.1+1.zip/jtreg/lib/jtreg.jar /System/Volumes/Data/mesos/work_dir/jib-master/install/jtreg/7.1.1/1/bundles/jtreg-7.1.1+1.zip/jtreg/lib/junit-platform-console-standalone-1.8.2.jar /System/Volumes/Data/mesos/work_dir/jib-master/install/jtreg/7.1.1/1/bundles/jtreg-7.1.1+1.zip/jtreg/lib/testng-7.3.0.jar /System/Volumes/Data/mesos/work_dir/jib-master/install/jtreg/7.1.1/1/bundles/jtreg-7.1.1+1.zip/jtreg/lib/jcommander-1.78.jar /System/Volumes/Data/mesos/work_dir/jib-master/install/jtreg/7.1.1/1/bundles/jtreg-7.1.1+1.zip/jtreg/lib/guice-4.2.3.jar patch: java.base /System/Volumes/Data/mesos/work_dir/slaves/741e9afd-8c02-45c3-b2e2-9db1450d0832-S29068/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/a31e4f88-6a10-45e1-90d1-86e71a9cdbe2/runs/eb0ffd24-e8db-4702-9709-43223bc2925d/testoutput/test-support/jtreg_open_test_jdk_tier1_part2/patches/java.base Test Layer class path: /System/Volumes/Data/mesos/work_dir/slaves/741e9afd-8c02-45c3-b2e2-9db1450d0832-S29068/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/a31e4f88-6a10-45e1-90d1-86e71a9cdbe2/runs/eb0ffd24-e8db-4702-9709-43223bc2925d/testoutput/test-support/jtreg_open_test_jdk_tier1_part2/classes/2/java/util/concurrent/forkjoin/AsyncShutdownNow.d /System/Volumes/Data/mesos/work_dir/jib-master/install/jdk-21+16-1321/src.full/open/test/jdk/java/util/concurrent/forkjoin ----------rerun:(28/5597)*---------- <snip> result: Error. Agent error: java.lang.Exception: Agent 6 timed out with a timeout of 480 seconds; check console log for any additional details
29-03-2023
Updates are now at https://github.com/DougLea/jdk/tree/JDK-8288899 . These have passed over a million test runs on x86 machines I have, but it would be helpful if someone could check them on others before issuing PR.
24-12-2022
This test has been changed by JDK-8296405 to improve its execution time, it now runs sub-second when it used to take ~40s. The updated test reproduces the hang in invokeAny a lot more frequently, esp. on Windows. Doug believes this is the same issue as JDK-828899. To avoid intermittent failures, testInvokeAny is temproarily disabled (with `enabled=false`) and will need to be re-enabled when the issue is fixed. ProblemList.txt can't be used at this time for this fine grain exclusion.
17-11-2022
This is likely the same issue as JDK-8288899 where threads are starting up as the FJP is being shutdown.
12-11-2022
I've attached an improved version of AsyncShutdownNow that replaces the 5 second sleep with a poll of the thread state. This allows it to run sub-second. While testing I did observe the issue reported here with a "test repeat" job but only on Windows with hundreds of runs. It seems the main thread is blocked in invokeAny waiting on the root task but the FJP has been shutdown and reports itself as terminated.
16-10-2022
None of the maintainers can reproduce this failure. I see that the test assumes it can give up after waiting 5 seconds, shorter than Martin's battle-tested 10 second rule. If the process stalls for 5 seconds (unlikely!), it could cause the failure seen here. I also see that Martin never followed up on his // TODO: this test is far too slow
12-06-2022
I don't think there isn't loom specific here. The timeout seems to be that shutdown when the test is waiting in invokeAny: "AgentVMThread" #210 [29104] prio=5 os_prio=0 cpu=31.25ms elapsed=491.34s allocated=833K defined_classes=17 tid=0x00000196fbe132b0 nid=29104 waiting on condition [0x0000003d48bfd000] java.lang.Thread.State: WAITING (parking) at jdk.internal.misc.Unsafe.park(java.base@19-loomvt/Native Method) - parking to wait for <0x00000000d0f87150> (a java.util.concurrent.ForkJoinPool$InvokeAnyRoot) at java.util.concurrent.locks.LockSupport.park(java.base@19-loomvt/LockSupport.java:371) at java.util.concurrent.ForkJoinTask.awaitDone(java.base@19-loomvt/ForkJoinTask.java:461) at java.util.concurrent.ForkJoinTask.get(java.base@19-loomvt/ForkJoinTask.java:991) at java.util.concurrent.ForkJoinPool.invokeAny(java.base@19-loomvt/ForkJoinPool.java:3095) at AsyncShutdownNow.testInvokeAny(AsyncShutdownNow.java:169) at java.lang.invoke.DirectMethodHandle$Holder.invokeVirtual(java.base@19-loomvt/DirectMethodHandle$Holder) at java.lang.invoke.LambdaForm$MH/0x00000001001aac00.invoke(java.base@19-loomvt/LambdaForm$MH) at java.lang.invoke.Invokers$Holder.invokeExact_MT(java.base@19-loomvt/Invokers$Holder) at jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(java.base@19-loomvt/DirectMethodHandleAccessor.java:155) at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(java.base@19-loomvt/DirectMethodHandleAccessor.java:104) at java.lang.reflect.Method.invoke(java.base@19-loomvt/Method.java:578) at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132) at org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:599) at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174) at org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46) at org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822) at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147) at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146) at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128) at org.testng.TestRunner$$Lambda$123/0x000000010012af30.accept(Unknown Source) at java.util.ArrayList.forEach(java.base@19-loomvt/ArrayList.java:1511) at org.testng.TestRunner.privateRun(TestRunner.java:764) at org.testng.TestRunner.run(TestRunner.java:585) at org.testng.SuiteRunner.runTest(SuiteRunner.java:384) at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378) at org.testng.SuiteRunner.privateRun(SuiteRunner.java:337) at org.testng.SuiteRunner.run(SuiteRunner.java:286) at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53) at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96) at org.testng.TestNG.runSuitesSequentially(TestNG.java:1218) at org.testng.TestNG.runSuitesLocally(TestNG.java:1140) at org.testng.TestNG.runSuites(TestNG.java:1069) at org.testng.TestNG.run(TestNG.java:1037) at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:94) at java.lang.invoke.LambdaForm$DMH/0x0000000100101400.invokeStatic(java.base@19-loomvt/LambdaForm$DMH) at java.lang.invoke.LambdaForm$MH/0x0000000100102400.invoke(java.base@19-loomvt/LambdaForm$MH) at java.lang.invoke.LambdaForm$MH/0x0000000100102800.invokeExact_MT(java.base@19-loomvt/LambdaForm$MH) at jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(java.base@19-loomvt/DirectMethodHandleAccessor.java:156) at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(java.base@19-loomvt/DirectMethodHandleAccessor.java:104) at java.lang.reflect.Method.invoke(java.base@19-loomvt/Method.java:578) at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312) at java.lang.Thread.run(java.base@19-loomvt/Thread.java:1585)
07-05-2022