RFR: 8270100: Fix some inaccurate GC logging

[Volker Simonis]

On Fri, 9 Jul 2021 08:05:45 GMT, Albert Mingkun Yang <ayang at openjdk.org> wrote:

>> If running with `-Xlog:gc+heap*=trace` the JVM will print the extra per thread amount which is added to the new generation on resize:
>> 
>> [0,105s][debug][gc,ergo,heap ] GC(0) New generation size 34112K->34176K [eden=27392K,survivor=3392K]
>> [0,105s][trace][gc,ergo,heap ] GC(0) [allowed 0K extra for 0 threads]
>> 
>> Currently this will always print "0K extra for 0 threads" no matter how much extra space was added.
>> 
>> Also, the shrink factor will always be printed to be 0%, even if we run with `-XX:-ShrinkHeapInSteps` which pins the shrink factor at 100%:
>> 
>> [13,213s][trace][gc,heap ] GC(34) shrink_bytes: 463564,0K current_shrink_factor: 0 new shrink factor: 0 _min_heap_delta_bytes: 192,0K
>> [13,239s][trace][gc,heap ] GC(34) Shrinking tenured generation from 531852K to 68288K
>> 
>> 
>> The fix is trivial.
>
> Can you share the complete flags and the benchmark for easy reproducing? Somehow I can't reproduce the gc logs; the flags and the benchmark I used:
> 
> `java -XX:+UseSerialGC -Xms2g -Xmx2g  '-Xlog:gc,gc+heap*=trace:gc.log::filecount=0' -jar dacapo-9.12-MR1-bach.jar h2 -s huge -n 1`

Hi @albertnetymk,

to see the first issue, you have to make the initial heap smaller than the the maximum heap. It can easily seen with your command line. Before the change:

$ java -XX:+UseSerialGC -Xms100m -Xmx2g '-Xlog:gc,gc+heap*=trace' -jar /share/soware/Java/dacapo-9.12-MR1-bach.jar h2 -s huge -n 1 | grep "allowed 0K extra"
[1,339s][trace][gc,ergo,heap ] GC(11)   [allowed 0K extra for 0 threads]
[2,066s][trace][gc,ergo,heap ] GC(17)   [allowed 0K extra for 0 threads]
[3,323s][trace][gc,ergo,heap ] GC(23)   [allowed 0K extra for 0 threads]
[5,560s][trace][gc,ergo,heap ] GC(29)   [allowed 0K extra for 0 threads]
...

After the change:

$ java -XX:+UseSerialGC -Xms100m -Xmx2g '-Xlog:gc,gc+heap*=trace' -jar /share/soware/Java/dacapo-9.12-MR1-bach.jar h2 -s huge -n 1 | grep "allowed 0K extra"
[1,397s][trace][gc,ergo,heap ] GC(11)   [allowed 5K extra for 1 threads]
[2,202s][trace][gc,ergo,heap ] GC(17)   [allowed 5K extra for 1 threads]
[3,468s][trace][gc,ergo,heap ] GC(23)   [allowed 5K extra for 1 threads]
[5,699s][trace][gc,ergo,heap ] GC(29)   [allowed 5K extra for 1 threads]
...
``` 

To see the second issue, you obviously will have to shrink the heap and set `-XX:-ShrinkHeapInSteps`. You can use the `Uncommit.java` program attached below. Before the change:

$ java -XX:+UseSerialGC -Xms100m -Xmx1g '-Xlog:gc,gc+heap*=trace' -XX:-ShrinkHeapInSteps Uncommit
...
[9,759s][trace][gc,heap      ] GC(11)     shrinking:  initSize: 68288,0K  maximum_desired_capacity: 90337,3K
[9,759s][trace][gc,heap      ] GC(11)     shrink_bytes: 572226,7K  current_shrink_factor: 0  new shrink factor: 0  _min_heap_delta_bytes: 192,0K
[9,780s][trace][gc,heap      ] GC(11) Shrinking tenured generation from 662564K to 90340K
...

After the change:

$ java -XX:+UseSerialGC -Xms100m -Xmx1g '-Xlog:gc,gc+heap*=trace' -XX:-ShrinkHeapInSteps Uncommit
...
[3,941s][trace][gc,heap      ] GC(11)     shrinking:  initSize: 68288,0K  maximum_desired_capacity: 92130,6K
[3,941s][trace][gc,heap      ] GC(11)     shrink_bytes: 575773,4K  current_shrink_factor: 100  new shrink factor: 100  _min_heap_delta_bytes: 192,0K
[3,958s][trace][gc,heap      ] GC(11) Shrinking tenured generation from 667904K to 92132K
...


Here's the example program:

import java.io.IOException;
import java.nio.file.FileSystems;
import java.nio.file.Files;
import java.nio.file.Path;

public class Uncommit {

  static class KB {
    int[] kb;
    public KB() {
      kb = new int[256];
    }
  }

  static class MB {
    KB[] mb;
    public MB() {
      mb = new KB[1024];
      for (int i = 0; i < mb.length; i++) {
        mb[i] = new KB();
      }
    }
  }

  static class GB {
    MB[] gb;
    public GB() {
      gb = new MB[1024];
      for (int i = 0; i < gb.length; i++) {
        gb[i] = new MB();
      }
    }
  }

  static void printRSS() throws IOException {
    Files.lines(FileSystems.getDefault().getPath("/proc/self/status")).
      filter(l -> l.startsWith("VmRSS")).
      forEach(System.out::println);
  }

  public static void main(String[] args) throws Exception {
    System.out.println("Calling System.gc()");
    System.gc();
    printRSS();
    System.out.println("\nPress <Enter>");
    System.console().readLine();

    int size = Integer.parseInt(args.length > 0 ? args[0] : "512");
    MB mb[] = new MB[size];
    for (int i = 0; i < size; i++) {
      mb[i] = new MB();
    }
    System.out.println("Successfully allocated " + size + "MB memory");
    printRSS();
    System.out.println("\nPress <Enter>");
    System.console().readLine();
    for (int i = 0; i < size; i++) {
      mb[i] = null;
    }
    System.out.println("Successfully unlinked " + size + "MB memory");
    printRSS();
    System.out.println("\nPress <Enter>");
    System.console().readLine();
    int gcs = 5;
    if (args.length > 1) {
      gcs = Integer.parseInt(args[1]);
    }
    for (int i = 1; i <= gcs; i++) {
      System.gc();
      System.out.println("Performed " + i + ". System.gc()\n");
      printRSS();
      System.out.println("Press <Enter>");
      System.console().readLine();
      }
  }
}

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

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