Balanced GC policy slows the write of a gzip file

dasilvj commented 1 year ago

The write of a 50MB gzip file using java.util.zip.GZIPOutputStream takes less than a second using the default GC policy. Using the balanced GC policy (-Xgcpolicy:balanced), it takes a few minutes.

Issue spotted using the following versions on Windows & Linux:

IBM Semeru Runtime
17.0.5.0
OpenJDK 17.0.5+8
OpenJ9 0.35.0
Windows

IBM Semeru Runtime
17.0.4.1
OpenJDK 17.0.4.1+1
OpenJ9 0.33.1
Linux

Reproducible with the following Java main:

import java.io.ByteArrayOutputStream;
import java.io.DataOutputStream;
import java.io.IOException;
import java.nio.charset.StandardCharsets;
import java.nio.file.Files;
import java.nio.file.Path;
import java.time.Duration;
import java.util.HashMap;
import java.util.Map;
import java.util.SortedSet;
import java.util.TreeSet;
import java.util.zip.GZIPOutputStream;

public class TestOpenJ9GCBalancedGZipOutputStreamIssue {

  public static void main(final String[] args) throws IOException {
    int[] NB_VALUES_SCENARIOS = new int[] {
        10_000, 100_000, 1_000_000, 10_000_000
    };

    for (int i = 0; i < NB_VALUES_SCENARIOS.length; i++) {
      final int nbValues = NB_VALUES_SCENARIOS[i];

      final byte[] dataBytes = getDataBytesForNumberOfValues(nbValues);
      final Path newPartitionFile =
          Files.createTempFile(TestOpenJ9GCBalancedGZipOutputStreamIssue.class.getSimpleName(), "");
      System.out.println("Write GZIP file '" + newPartitionFile.toAbsolutePath() + "' with '"
          + nbValues + "' values");
      try (final DataOutputStream dos =
          new DataOutputStream(new GZIPOutputStream(Files.newOutputStream(newPartitionFile)))) {
        final long startTimeInNS = System.nanoTime();
        System.out.println("BEGIN_WRITE [dataBytesLen='" + dataBytes.length + "']");
        dos.write(dataBytes);
        System.out.println("END_WRITE [durationInMillis='"
            + Duration.ofNanos(System.nanoTime() - startTimeInNS).toMillis() + "']");
      } finally {
        if (Files.deleteIfExists(newPartitionFile)) {
          System.out.println("Deleted '" + newPartitionFile.toAbsolutePath() + "'");
        }
      }
    }
  }

  private static final byte[] getDataBytesForNumberOfValues(final int nbValues) throws IOException {
    final Map<String, SortedSet<String>> partitionData = new HashMap<>();
    final SortedSet<String> keyData = new TreeSet<>();
    for (int i = 0; i < nbValues; i++) {
      keyData.add(TestOpenJ9GCBalancedGZipOutputStreamIssue.class.getSimpleName() + i);
    }
    partitionData.put(TestOpenJ9GCBalancedGZipOutputStreamIssue.class.getSimpleName() + "-1",
        keyData);

    final byte[] dataBytes;
    try (final ByteArrayOutputStream dataBOS = new ByteArrayOutputStream()) {
      try (final DataOutputStream dataDOS = new DataOutputStream(dataBOS)) {
        for (final Map.Entry<String, SortedSet<String>> partitionDataEntry : partitionData
            .entrySet()) {
          for (final String dataValue : partitionDataEntry.getValue()) {
            final byte[] dataValueBytes = dataValue.getBytes(StandardCharsets.UTF_8);
            dataDOS.writeInt(dataValueBytes.length);
            dataDOS.write(dataValueBytes);
          }
        }
        dataDOS.flush();
      }

      dataBytes = dataBOS.toByteArray();
    }

    return dataBytes;
  }
}

Default GC main output

Write GZIP file 'C:\Users\xxx\AppData\Local\Temp\TestOpenJ9GCBalancedGZipOutputStreamIssue12309753225143979752' with '10000' values
BEGIN_WRITE [dataBytesLen='488890']
END_WRITE [durationInMillis='4']
Deleted 'C:\Users\xxx\AppData\Local\Temp\TestOpenJ9GCBalancedGZipOutputStreamIssue12309753225143979752'
Write GZIP file 'C:\Users\xxx\AppData\Local\Temp\TestOpenJ9GCBalancedGZipOutputStreamIssue12665477723083095111' with '100000' values
BEGIN_WRITE [dataBytesLen='4988890']
END_WRITE [durationInMillis='37']
Deleted 'C:\Users\xxx\AppData\Local\Temp\TestOpenJ9GCBalancedGZipOutputStreamIssue12665477723083095111'
Write GZIP file 'C:\Users\xxx\AppData\Local\Temp\TestOpenJ9GCBalancedGZipOutputStreamIssue3017559964530800524' with '1000000' values
BEGIN_WRITE [dataBytesLen='50888890'] // 50MB
END_WRITE [durationInMillis='335']
Deleted 'C:\Users\xxx\AppData\Local\Temp\TestOpenJ9GCBalancedGZipOutputStreamIssue3017559964530800524'
Write GZIP file 'C:\Users\xxx\AppData\Local\Temp\TestOpenJ9GCBalancedGZipOutputStreamIssue7180190478736843458' with '10000000' values
BEGIN_WRITE [dataBytesLen='518888890'] // 500MB
END_WRITE [durationInMillis='3447']
Deleted 'C:\Users\xxx\AppData\Local\Temp\TestOpenJ9GCBalancedGZipOutputStreamIssue7180190478736843458'

Balanced GC main output

Write GZIP file 'C:\Users\xxx\AppData\Local\Temp\TestOpenJ9GCBalancedGZipOutputStreamIssue8240261865019036048' with '10000' values
BEGIN_WRITE [dataBytesLen='488890']
END_WRITE [durationInMillis='4']
Deleted 'C:\Users\xxx\AppData\Local\Temp\TestOpenJ9GCBalancedGZipOutputStreamIssue8240261865019036048'
Write GZIP file 'C:\Users\xxx\AppData\Local\Temp\TestOpenJ9GCBalancedGZipOutputStreamIssue7864815220160303440' with '100000' values
BEGIN_WRITE [dataBytesLen='4988890']
END_WRITE [durationInMillis='1692']
Deleted 'C:\Users\xxx\AppData\Local\Temp\TestOpenJ9GCBalancedGZipOutputStreamIssue7864815220160303440'
Write GZIP file 'C:\Users\xxx\AppData\Local\Temp\TestOpenJ9GCBalancedGZipOutputStreamIssue9170858169658686901' with '1000000' values
BEGIN_WRITE [dataBytesLen='50888890']
END_WRITE [durationInMillis='177585']
Deleted 'C:\Users\xxx\AppData\Local\Temp\TestOpenJ9GCBalancedGZipOutputStreamIssue9170858169658686901'
Write GZIP file 'C:\Users\xxx\AppData\Local\Temp\TestOpenJ9GCBalancedGZipOutputStreamIssue12928817364060116750' with '10000000' values
BEGIN_WRITE [dataBytesLen='518888890']
........... still running (-: