JDK-8225186 : gc/g1/humongousObjects/TestHumongousClassLoader.java timed out
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 13,18
  • Priority: P3
  • Status: Closed
  • Resolution: Cannot Reproduce
  • OS: linux
  • CPU: x86_64
  • Submitted: 2019-06-03
  • Updated: 2022-07-20
  • Resolved: 2022-07-20
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 19
19Resolved
Related Reports
Relates :  
JDK-8217170 - gc/arguments/TestUseCompressedOopsErgo.java timed out
Description
Loading class HumongousClassLoader
[2019-06-03T10:36:55.726467Z] Gathering output for process 21426
[2019-06-03T10:36:56.641312Z] Waiting for completion for process 21426
[2019-06-03T10:37:41.406604Z] Waiting for completion finished for process 21426
[2019-06-03T10:37:41.492604Z] Gathering output for process 21817
[2019-06-03T10:37:41.525059Z] Waiting for completion for process 21817
[2019-06-03T10:38:08.928703Z] Waiting for completion finished for process 21817
Loading class LargestNonHumongousClass
[2019-06-03T10:38:09.726428Z] Gathering output for process 22010
[2019-06-03T10:38:09.732610Z] Waiting for completion for process 22010
[2019-06-03T10:38:49.926177Z] Waiting for completion finished for process 22010
[2019-06-03T10:38:49.970013Z] Gathering output for process 22173
[2019-06-03T10:38:49.982667Z] Waiting for completion for process 22173
[2019-06-03T10:39:16.103569Z] Waiting for completion finished for process 22173
Loading class SmallestHumongousClass
[2019-06-03T10:39:17.823677Z] Gathering output for process 22808
[2019-06-03T10:39:17.853217Z] Waiting for completion for process 22808
[2019-06-03T10:39:58.776077Z] Waiting for completion finished for process 22808
[2019-06-03T10:39:59.389712Z] Gathering output for process 23415
[2019-06-03T10:39:59.414777Z] Waiting for completion for process 23415
[2019-06-03T10:40:44.853371Z] Waiting for completion finished for process 23415
[2019-06-03T10:40:44.899760Z] Gathering output for process 23999
[2019-06-03T10:40:44.939926Z] Waiting for completion for process 23999
[2019-06-03T10:41:21.240659Z] Waiting for completion finished for process 23999
Loading class OneRegionHumongousClass
[2019-06-03T10:41:24.814534Z] Gathering output for process 24240
[2019-06-03T10:41:24.834228Z] Waiting for completion for process 24240
[2019-06-03T10:42:35.032240Z] Waiting for completion finished for process 24240
[2019-06-03T10:42:39.981380Z] Gathering output for process 24544
[2019-06-03T10:42:39.991806Z] Waiting for completion for process 24544
[2019-06-03T10:44:07.372384Z] Waiting for completion finished for process 24544
[2019-06-03T10:44:07.456386Z] Gathering output for process 24889
[2019-06-03T10:44:07.466738Z] Waiting for completion for process 24889
Timeout refired 480 times
[2019-06-03T10:44:59.192371Z] Waiting for completion finished for process 24889
Loading class TwoRegionHumongousClass
Comments
Closing as CNR as the last occurrence has been in July 2021 and has not reproduced since.
20-07-2022
Here's log file snippets for the jdk-18+4-124-tier1 sighting: #section:main ----------messages:(7/821)---------- command: main -Xms256M -Xmx256M -XX:+UseG1GC -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -Xbootclasspath/a:. -Xlog:class+load,class+unload=debug:file=TestHumongousClassLoader_Full_GC.log -XX:G1HeapRegionSize=1M gc.g1.humongousObjects.TestHumongousClassLoader FULL_GC reason: User specified action: run main/othervm -Xms256M -Xmx256M -XX:+UseG1GC -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -Xbootclasspath/a:. -Xlog:class+load,class+unload=debug:file=TestHumongousClassLoader_Full_GC.log -XX:G1HeapRegionSize=1M gc.g1.humongousObjects.TestHumongousClassLoader FULL_GC Mode: othervm [/othervm specified] Additional options from @modules: --add-modules java.base,java.management --add-exports java.base/jdk.internal.misc=ALL-UNNAMED Timeout information: --- Timeout information end. elapsed time (seconds): 840.75 ----------configuration:(4/111)---------- Boot Layer add modules: java.base java.management add exports: java.base/jdk.internal.misc ALL-UNNAMED ----------System.out:(36/2523)---------- Loading class HumongousClassLoader [2021-06-30T22:55:46.326141996Z] Gathering output for process 4146135 [2021-06-30T22:55:47.971064969Z] Waiting for completion for process 4146135 [2021-06-30T22:56:28.752298533Z] Waiting for completion finished for process 4146135 [2021-06-30T22:56:28.964457950Z] Gathering output for process 4146246 [2021-06-30T22:56:28.988024245Z] Waiting for completion for process 4146246 [2021-06-30T22:57:09.483688181Z] Waiting for completion finished for process 4146246 Loading class LargestNonHumongousClass [2021-06-30T22:57:09.832383877Z] Gathering output for process 4146328 [2021-06-30T22:57:09.840477816Z] Waiting for completion for process 4146328 [2021-06-30T22:58:02.072994803Z] Waiting for completion finished for process 4146328 [2021-06-30T22:58:02.181141337Z] Gathering output for process 4146481 [2021-06-30T22:58:02.181677418Z] Waiting for completion for process 4146481 [2021-06-30T22:58:30.752439701Z] Waiting for completion finished for process 4146481 Loading class SmallestHumongousClass [2021-06-30T22:58:31.247695501Z] Gathering output for process 4146620 [2021-06-30T22:58:31.260107890Z] Waiting for completion for process 4146620 [2021-06-30T22:59:15.263232761Z] Waiting for completion finished for process 4146620 [2021-06-30T22:59:15.329296635Z] Gathering output for process 4146833 [2021-06-30T22:59:15.330152957Z] Waiting for completion for process 4146833 [2021-06-30T23:00:10.895038990Z] Waiting for completion finished for process 4146833 [2021-06-30T23:00:10.971932930Z] Gathering output for process 4147045 [2021-06-30T23:00:10.972558011Z] Waiting for completion for process 4147045 [2021-06-30T23:01:28.703658178Z] Waiting for completion finished for process 4147045 Loading class OneRegionHumongousClass [2021-06-30T23:01:28.836094168Z] Gathering output for process 4147244 [2021-06-30T23:01:28.856399656Z] Waiting for completion for process 4147244 [2021-06-30T23:02:21.661904911Z] Waiting for completion finished for process 4147244 [2021-06-30T23:02:21.745039905Z] Gathering output for process 4147413 [2021-06-30T23:02:21.777829102Z] Waiting for completion for process 4147413 [2021-06-30T23:03:09.315948298Z] Waiting for completion finished for process 4147413 [2021-06-30T23:03:09.392615518Z] Gathering output for process 4147712 [2021-06-30T23:03:09.445533522Z] Waiting for completion for process 4147712 Timeout refired 480 times [2021-06-30T23:03:51.511662380Z] Waiting for completion finished for process 4147712 Loading class TwoRegionHumongousClass ----------System.err:(1/15)---------- STATUS:Passed. ----------rerun:(43/8298)*---------- <snip> result: Error. Program `/opt/mach5/mesos/work_dir/jib-master/install/jdk-18+4-124/linux-aarch64-debug.jdk/jdk-18/fastdebug/bin/java' timed out (timeout set to 480000ms, elapsed time including timeout handling was 840704ms). Please note that the test passed while the timeout handler was running. Here's top output captured by the timeout handler: top - 23:09:36 up 6 days, 18:19, 0 users, load average: 1.32, 4.45, 5.37 Tasks: 236 total, 1 running, 235 sleeping, 0 stopped, 0 zombie %Cpu(s): 0.6 us, 2.3 sy, 0.0 ni, 97.1 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st MiB Mem : 47613.1 total, 7756.7 free, 3802.8 used, 36053.6 buff/cache MiB Swap: 4095.9 total, 3992.7 free, 103.2 used. 36336.5 avail Mem This test machine doesn't appear to be overloaded to me...
30-06-2021
Has not reproduced for a long time. Reopen if it reoccurs.
16-07-2020
This looks similar to JDK-8217170, with surprisingly high "waiting for completion" times for the subprocesses. But this failure was on Linux, where JDK-8217170 has appeared to be Windows-specific.
07-06-2019
The test should probably split up into multiple tests (it has multiple @run clauses); also in that test, GC do not take long at all, but doing the class loading (seemingly 90% of time, e.g. 36s out of 40s when run locally).
06-06-2019