RFR: JDK-8148736: Let the G1 heap transition log regions instead of bytes

[Bengt Rutisson]

Hi everyone,

Could I have a couple of reviews for this change?

http://cr.openjdk.java.net/~brutisso/8148736/webrev.00/
https://bugs.openjdk.java.net/browse/JDK-8148736

(Note: the webrev is based on top of the change for JDK-8148733, 
JDK-8148734 and JDK-8148735 that are also currently out for review.)

As described in JDK-8147976 the way G1 now logs the used memory for 
eden, survivor, old and humongous can be confusing. It does not 
necessarily add up to the same value as the overall heap usage.

Instead log the number of regions each space is using. This should 
reduce the confusion. At trace level the exact usage can be logged.

The current logging (running with -Xlog:gc*) looks like this:

[1,395s][info   ][gc,start    ] GC(17) Pause Initial Mark (G1 Evacuation 
Pause) (1,395s)
[1,417s][info   ][gc,heap     ] GC(17) Eden: 61440K->0K(61440K)
[1,417s][info   ][gc,heap     ] GC(17) Survivor: 4096K->4096K(8192K)
[1,417s][info   ][gc,heap     ] GC(17) Old: 61440K->61440K
[1,417s][info   ][gc,heap     ] GC(17) Humongous: 0K->0K
[1,417s][info   ][gc,metaspace] GC(17) Metaspace: 2967K->2967K(1056768K)
[1,417s][info   ][gc          ] GC(17) Pause Initial Mark (G1 Evacuation 
Pause) 123M->63M(128M) (1,395s, 1,417s) 22,030ms
[1,417s][info   ][gc,cpu      ] GC(17) User=0,15s Sys=0,00s Real=0,02s


With the proposed change it will look like this:

[1,391s][info   ][gc,start    ] GC(17) Pause Initial Mark (G1 Evacuation 
Pause) (1,391s)
[1,407s][info   ][gc,heap     ] GC(17) Eden regions: 59->0(59)
[1,407s][info   ][gc,heap     ] GC(17) Survivor regions: 5->5(8)
[1,407s][info   ][gc,heap     ] GC(17) Old regions: 59->59
[1,407s][info   ][gc,heap     ] GC(17) Humongous regions: 0->0
[1,407s][info   ][gc,metaspace] GC(17) Metaspace: 2967K->2967K(1056768K)
[1,408s][info   ][gc          ] GC(17) Pause Initial Mark (G1 Evacuation 
Pause) 121M->63M(128M) (1,391s, 1,408s) 16,632ms
[1,408s][info   ][gc,cpu      ] GC(17) User=0,15s Sys=0,01s Real=0,02s


and if you run with -Xlog:gc*,gc+heap=trace you will get this:

[1,391s][trace  ][gc,heap     ] GC(17) Heap before GC invocations=17 
(full 0):
[1,391s][trace  ][gc,heap     ] GC(17)  garbage-first heap   total 
131072K, used 124885K [0x00000000f8000000, 0x00000000f8100400, 
0x0000000100000000)
[1,391s][trace  ][gc,heap     ] GC(17)   region size 1024K, 64 young 
(65536K), 5 survivors (5120K)
[1,391s][trace  ][gc,heap     ] GC(17)  Metaspace used 2967K, capacity 
4562K, committed 4864K, reserved 1056768K
[1,391s][trace  ][gc,heap     ] GC(17)   class space used 277K, capacity 
386K, committed 512K, reserved 1048576K
[1,391s][info   ][gc,start    ] GC(17) Pause Initial Mark (G1 Evacuation 
Pause) (1,391s)
[1,407s][info   ][gc,heap     ] GC(17) Eden regions: 59->0(59)
[1,407s][trace  ][gc,heap     ] GC(17)  Used: 0K, Waste: 0K
[1,407s][info   ][gc,heap     ] GC(17) Survivor regions: 5->5(8)
[1,407s][trace  ][gc,heap     ] GC(17)  Used: 4385K, Waste: 734K
[1,407s][info   ][gc,heap     ] GC(17) Old regions: 59->59
[1,407s][trace  ][gc,heap     ] GC(17)  Used: 60331K, Waste: 85K
[1,407s][info   ][gc,heap     ] GC(17) Humongous regions: 0->0
[1,407s][trace  ][gc,heap     ] GC(17)  Used: 0K, Waste: 0K
[1,407s][info   ][gc,metaspace] GC(17) Metaspace: 2967K->2967K(1056768K)
[1,407s][trace  ][gc,heap     ] GC(17) Heap after GC invocations=18 
(full 0):
[1,408s][trace  ][gc,heap     ] GC(17)  garbage-first heap   total 
131072K, used 64716K [0x00000000f8000000, 0x00000000f8100400, 
0x0000000100000000)
[1,408s][trace  ][gc,heap     ] GC(17)   region size 1024K, 5 young 
(5120K), 5 survivors (5120K)
[1,408s][trace  ][gc,heap     ] GC(17)  Metaspace used 2967K, capacity 
4562K, committed 4864K, reserved 1056768K
[1,408s][trace  ][gc,heap     ] GC(17)   class space used 277K, capacity 
386K, committed 512K, reserved 1048576K
[1,408s][info   ][gc          ] GC(17) Pause Initial Mark (G1 Evacuation 
Pause) 121M->63M(128M) (1,391s, 1,408s) 16,632ms
[1,408s][info   ][gc,cpu      ] GC(17) User=0,15s Sys=0,01s Real=0,02s


Thanks,
Bengt