RFR: 8267311: vmTestbase/gc/gctests/StringInternGC/StringInternGC.java fails when JTREG_JOBS > 25

[Thomas Schatzl]

On Tue, 18 May 2021 09:42:31 GMT, Jie Fu <jiefu at openjdk.org> wrote:

> Hi all,
> 
> vmTestbase/gc/gctests/StringInternGC/StringInternGC.java fails with release VM on our many-core machines due to `-XX:MaxRAMPercentage=0`.
> This is because `-XX:MaxRAMPercentage=0` will be 0 if JTREG_JOBS > 25 [1].
> 
> Reproduce:
>  - make test TEST="vmTestbase/gc/gctests/StringInternGC/StringInternGC.java" JTREG="JOBS=26" CONF=server-release
> 
> `-Xmx1g` is added to make it more robust.
> Note: we still see failure with `-Xmx512m`.
> 
> Thanks.
> Best regards,
> Jie
> 
> [1] https://github.com/openjdk/jdk/blob/master/make/RunTests.gmk#L741

I still can't reproduce it on my machine on linux-x64. Neither with fastdebug, nor with release builds, with the same random seed. All variations of `@run main/othervm -Djdk.test.lib.random.seed=-6595041523873090927 -XX:MaxRAMPercentage=0 -XX:+PrintFlagsFinal -Xlog:gc gc.gctests.StringInternGC.StringInternGC` (i.e. with/without various of these options) pass.

In the log you pasted, the selected heap size is 128MB regardless of the given `MaxRAMPercentage` too.

Can you
* give information about the hardware and environment used. I suspect you are running on different, much slower hardware (mine is already like 7 year old now, and wasn't top-of-the-line then), and concurrent cycles can't keep up. However it is strange anyway because the resulting full gc should clean up any garbage. So something else idk about might kick in.
* without MaxRAMPercentage and look if `Max memory: 132120576` in the log changes?
* run with `-Xlog:gc` and provide a log snippet of the last few gc invocations?

Here's what I can see:
```Stress time: 30 seconds
Stress iterations factor: 1
Stress threads factor: 1
Stress runs factor: 1
Max memory: 132120576
Sleep time: 500
Iterations: 0
Number of threads: 4
Run GC thread: false
Run mem diag thread: false
Run forever: false
Starting Thread[gc.gctests.StringInternGC.StringInternGC$StringGenerator at 568bbaf2,5,MainThreadGroup]
Starting Thread[gc.gctests.StringInternGC.StringInternGC$StringGenerator at 3922f95b,5,MainThreadGroup]
Starting Thread[gc.gctests.StringInternGC.StringInternGC$StringGenerator at 32f588a7,5,MainThreadGroup]
Starting Thread[gc.gctests.StringInternGC.StringInternGC$StringGenerator at 40e1cd09,5,MainThreadGroup]
For random generator using seed: -6595041523873090927
To re-run test with same seed value please add "-Djdk.test.lib.random.seed=-6595041523873090927" to command line.
[0.319s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 22M->2M(126M) 3.351ms
[0.347s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 47M->2M(126M) 2.678ms
[0.368s][info][gc] GC(2) Pause Young (Normal) (G1 Evacuation Pause) 72M->3M(126M) 2.759ms
[0.392s][info][gc] GC(3) Pause Young (Normal) (G1 Evacuation Pause) 74M->3M(126M) 2.431ms
[...]
[30.214s][info][gc] GC(7510) Pause Young (Concurrent Start) (G1 Humongous Allocation) 53M->53M(126M) 0.621ms
[30.214s][info][gc] GC(7511) Concurrent Undo Cycle
[30.214s][info][gc] GC(7511) Concurrent Undo Cycle 0.135ms
[30.220s][info][gc] GC(7512) Pause Young (Concurrent Start) (G1 Humongous Allocation) 71M->59M(126M) 0.647ms
[30.220s][info][gc] GC(7513) Concurrent Mark Cycle
[30.228s][info][gc] GC(7513) Pause Remark 74M->74M(126M) 0.558ms
[30.229s][info][gc] GC(7513) Pause Cleanup 111M->111M(126M) 0.085ms
[30.230s][info][gc] GC(7513) Concurrent Mark Cycle 9.699ms
[30.235s][info][gc] GC(7514) Pause Young (Concurrent Start) (G1 Humongous Allocation) 111M->53M(126M) 0.788ms
[30.235s][info][gc] GC(7515) Concurrent Undo Cycle
[30.238s][info][gc] GC(7515) Concurrent Undo Cycle 2.442ms
[30.248s][info][gc] GC(7516) Pause Young (Concurrent Start) (G1 Humongous Allocation) 90M->59M(126M) 0.818ms
[30.248s][info][gc] GC(7517) Concurrent Mark Cycle
[30.256s][info][gc] GC(7517) Pause Remark 96M->96M(126M) 0.584ms
[30.259s][info][gc] GC(7518) Pause Young (Normal) (G1 Humongous Allocation) 117M->53M(126M) 0.681ms
[30.266s][info][gc] GC(7517) Pause Cleanup 68M->68M(126M) 0.069ms
[30.266s][info][gc] GC(7517) Concurrent Mark Cycle 17.522ms
[30.274s][info][gc] GC(7519) Pause Young (Concurrent Start) (G1 Humongous Allocation) 87M->53M(126M) 0.788ms
[30.274s][info][gc] GC(7520) Concurrent Undo Cycle
[30.275s][info][gc] GC(7520) Concurrent Undo Cycle 1.292ms
[30.281s][info][gc] GC(7521) Pause Young (Concurrent Start) (G1 Humongous Allocation) 78M->53M(126M) 0.680ms
[30.281s][info][gc] GC(7522) Concurrent Undo Cycle
[30.282s][info][gc] GC(7522) Concurrent Undo Cycle 0.131ms
No unexpected exceptions/errors are thrown


So lots and lots of concurrent cycles, undos in this case.

-------------

PR: https://git.openjdk.java.net/jdk/pull/4086