JDK-8269262 : ZGC: misc vmTestbase/vm/gc tests timed out
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 17,18
  • Priority: P4
  • Status: Closed
  • Resolution: Cannot Reproduce
  • OS: windows
  • CPU: x86_64
  • Submitted: 2021-06-23
  • Updated: 2022-11-30
  • Resolved: 2022-11-29
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 20
20Resolved
Related Reports
Relates :  
JDK-8267484 - misc vmTestbase/gc/gctests timed out on a particular machine
Description
The following test timed out in the JDK18 CI:

vmTestbase/vm/gc/containers/LinkedList_Arrays/TestDescription.java

Here's a snippet from the log file:

#section:main
----------messages:(6/377)----------
command: main -XX:-UseGCOverheadLimit vm.gc.containers.ContainersTest -ms low -ct LinkedList(random(arrays))
reason: User specified action: run main/othervm -XX:-UseGCOverheadLimit vm.gc.containers.ContainersTest -ms low -ct LinkedList(random(arrays)) 
Mode: othervm [/othervm specified]
Timeout information:
--- Timeout information end.
elapsed time (seconds): 4727.016
----------configuration:(0/0)----------
----------System.out:(39/2530)----------
Stress time: 300 seconds
Stress iterations factor: 1
Stress threads factor: 1
Stress runs factor: 1
Max memory: 2136997888
Sleep time: 500
Iterations: 0
Number of threads: 24
Run GC thread: false
Run mem diag thread: false
Run forever: false
Starting Thread[vm.gc.containers.ContainersTest$Mutator@7460fb59,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@7468b21c,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@7a135fb,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@93c7a23,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@5795cf84,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@665c6f38,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@685c80e5,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@25b02af,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@7b4b148f,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@7eeb9171,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@723c7de1,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@28284773,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@be4c195,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@2926b981,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@38640a31,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@521dc191,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@7fd84a2e,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@63ae1ee5,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@7b83b523,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@472ef28b,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@7a1a497a,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@69d039ea,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@f1cb35e,5,MainThreadGroup]
Starting Thread[vm.gc.containers.ContainersTest$Mutator@3f96b29c,5,MainThreadGroup]
For random generator using seed: -1168484051468025664
To re-run test with same seed value please add "-Djdk.test.lib.random.seed=-1168484051468025664" to command line.
Timeout refired 1200 times
No unexpected exceptions/errors are thrown
----------System.err:(25/1144)----------
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
Creating container: size = 100 count = 277809
STATUS:Passed.
----------rerun:(42/6239)*----------

<snip>

result: Error. Program `c:\ade\mesos\work_dir\jib-master\install\jdk-18+3-53\windows-x64.jdk\jdk-18\bin\java' timed out (timeout set to 1200000ms, elapsed time including timeout handling was 2312763ms).


Here's the test task's JVM args: -XX:+CreateCoredumpOnCrash -XX:+UseZGC
Comments
[~dcubed] I'm not so sure about that. I personally don't think this is an issue with the JVM, therefore I closed this as "Not an issue". The same comment goes for the other bug you updated. Having said that, I'm also OK with having this set to CNR.
30-11-2022
Closing as CNR (Cannot Reproduce) is more appropriate for something that hasn't been seen in a long time.
29-11-2022
Most likely caused by slow Win machine.
29-11-2022
I still don't think this has anything to do with the GC. Some observations from the runs: This is from the gc logs from the last two incidences: [52.552s][info][gc] Using The Z Garbage Collector [582.429s][info][gc] GC(0) Garbage Collection (Warmup) 90M(4%)->670M(33%) [582.650s][info][gc] Allocation Stall (gc.ArrayJuggle.Juggle01.Juggle01$Juggler@546b91a9) 16.632ms [582.651s][info][gc] Allocation Stall (gc.ArrayJuggle.Juggle01.Juggle01$Juggler@578e098c) 16.943ms [52.147s][info][gc] Using The Z Garbage Collector [594.648s][info][gc] GC(0) Garbage Collection (System.gc()) 28M(1%)->168M(8%) [594.905s][info][gc] GC(1) Garbage Collection (System.gc()) 640M(31%)->388M(19%) [594.979s][info][gc] GC(2) Garbage Collection (System.gc()) 398M(20%)->408M(20%) In both cases it takes 52 seconds to just initialize the GC, and then over 500 seconds (more than the test timeout) to get to the first GC. Note also that just compiling the test took ~30 seconds: compile: gc.ArrayJuggle.Juggle01.Juggle01 elapsed time (seconds): 29.447 I'm not sure if the increase is caused by jtreg serializing the builds (have seen similar problems before with the test runs), or if the times actually increase. compile: 11.397 seconds compile: 15.611 seconds compile: 18.392 seconds compile: 23.17 seconds compile: 25.296 seconds Just before both failures, the main tasks increases to >140 seconds, while the other runs take ~120 seconds: main: 144.378 seconds main: 145.305 seconds
18-02-2022
Linking to JDK-8267484 which seems similar, but all these timeouts seem to appear on a different machine (but the same).
25-06-2021