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

```[119.980s][info][gc] GC(20072) Pause Young (Normal) (G1 Humongous Allocation) 101M->77M(126M) 0.404ms
[119.982s][info][gc] GC(20071) Pause Cleanup 89M->89M(126M) 0.039ms
[119.982s][info][gc] GC(20071) Concurrent Mark Cycle 22.748ms
[119.994s][info][gc] GC(20073) Pause Young (Concurrent Start) (G1 Humongous Allocation) 89M->77M(126M) 0.479ms
[119.994s][info][gc] GC(20074) Concurrent Mark Cycle
[120.008s][info][gc] GC(20074) Pause Remark 95M->95M(126M) 0.449ms
[120.009s][info][gc] GC(20075) Pause Young (Normal) (G1 Humongous Allocation) 101M->77M(126M) 0.397ms
[120.011s][info][gc] GC(20074) Pause Cleanup 89M->89M(126M) 0.047ms
[120.012s][info][gc] GC(20074) Concurrent Mark Cycle 17.564ms
[120.023s][info][gc] GC(20076) Pause Young (Concurrent Start) (G1 Humongous Allocation) 89M->77M(126M) 0.475ms
[120.023s][info][gc] GC(20077) Concurrent Mark Cycle
[120.037s][info][gc] GC(20077) Pause Remark 95M->95M(126M) 0.455ms
[120.038s][info][gc] GC(20078) Pause Young (Normal) (G1 Humongous Allocation) 101M->77M(126M) 0.387ms
[120.040s][info][gc] GC(20077) Pause Cleanup 89M->89M(126M) 0.047ms
[120.041s][info][gc] GC(20077) Concurrent Mark Cycle 17.251ms
[120.052s][info][gc] GC(20079) Pause Young (Concurrent Start) (G1 Humongous Allocation) 89M->77M(126M) 0.463ms
[120.052s][info][gc] GC(20080) Concurrent Mark Cycle
[120.066s][info][gc] GC(20080) Pause Remark 95M->95M(126M) 0.464ms
[120.066s][info][gc] GC(20080) Pause Cleanup 95M->95M(126M) 0.038ms
[120.066s][info][gc] GC(20080) Concurrent Mark Cycle 13.945ms
Failures summary:
java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space
        at java.base/java.util.Arrays.copyOfRange(Arrays.java:3821)
        at java.base/java.lang.StringUTF16.newString(StringUTF16.java:1179)
        at java.base/java.lang.StringBuffer.toString(StringBuffer.java:712)
        at gc.gctests.StringInternGC.StringInternGC$StringGenerator.generateString(StringInternGC.java:58)
        at gc.gctests.StringInternGC.StringInternGC$StringGenerator.run(StringInternGC.java:63)
        at nsk.share.runner.ThreadsRunner$ManagedThread.run(ThreadsRunner.java:106)
        at java.base/java.lang.Thread.run(Thread.java:831)```

The question that comes immediately to my mind here:
* where's the full gc to try to compact the heap?
* and after looking at the test, I think it is pretty dumb. The test code is like:

```public class StringInternGC extends ThreadedGCTest {
        private int maxLength = 1000;

        private class StringGenerator implements Runnable {
                private StringBuffer sb = new StringBuffer();

                private String generateString() {
                        int length = LocalRandom.nextInt(maxLength);
                        for (int i = 0; i < length; ++i)
                                sb.append((char) LocalRandom.nextInt(Integer.MAX_VALUE));
                        return sb.toString();
                }


                public void run() {
                        generateString().intern();
                }
        }


The test infinitely expands the original string instead of at least at some point cutting it off. Particularly if you've got a fast machine, it might extend it to be larger than any heap, and that is probably why the test just errors out without a GC at some point. This also explains why it only occurs with a release build at your place.

Please fix the test instead of working around the issue until next time we have to expand its -Xmx. Something like resetting the string after it reached a particular size (e.g. 128kb) should be enough to generate lots of unique strings.

Something like this:
```@@ -46,13 +46,17 @@ import nsk.share.gc.*;
  * String pool should not overflow.
  */
 public class StringInternGC extends ThreadedGCTest {
-        private int maxLength = 1000;
+        private int maxLength = 1000; // Maximum length to add per operation.
+        private int maxTotalLength = 128 * 1024; // Random total maximum length of the string.
 
         private class StringGenerator implements Runnable {
                 private StringBuffer sb = new StringBuffer();
 
                 private String generateString() {
                         int length = LocalRandom.nextInt(maxLength);
+                        if (sb.length() > maxTotalLength) {
+                          sb = new StringBuffer();
+                        }
                         for (int i = 0; i < length; ++i)
                                 sb.append((char) LocalRandom.nextInt(Integer.MAX_VALUE));
                         return sb.toString();


Voilà, all problems gone afaict - only young-only gcs, and afaict the string table is still highly stressed with unique strings :-) What I'm not completely sure is whether causing some string table unloading (via concurrent mark, full gc) the original test were supposed to occur. To not only stress addition of strings to the string table, this could be added by "regular" forced (concurrent) string table unloading (if not happening already).

If you agree that this fixes this problem, please change the CR title to match the problem ("StringInternGC eventually OOMEs" or so) and let's get the test fixed, not working around the problem.

I still think there is some bug in the script to let `MaxRAMPercentage` go down to zero, to be filed separately as mentioned before.

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

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