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

[Bengt Rutisson]

Hi Kirk,

On 2016-02-01 12:13, kirk.pepperdine at gmail.com wrote:
> Hi Bengt,
>
> Sorry but I hit the send too quickly. The occupancy numbers before and after the collection are the numbers that I’m not so happy losing. It is true that they never did add up but it was never more than what would be normal rounding error given that things are reported in K and M and not bytes. Even with the small errors, the numbers are incredibly useful.


If  you multiply the region numbers that are now logged with the region 
size you get the same occupancy numbers as before. It is hard to say if 
the difference is small or not. It depends on the fragmentation and the 
region size. In Jenny's example for JDK-8147976 the difference was > 1G 
for a 50G heap. I find that too much of a difference to make the numbers 
feel reliable. The proposed change makes it clearer what is going on and 
why the difference is there.

Regards,
Bengt

>
> Regards,
> Kirk
>
>> On Feb 1, 2016, at 11:53 AM, kirk.pepperdine at gmail.com wrote:
>>
>> Hi Bengt,
>>
>> I like the idea of having region counts being logged but I’m not very happy about losing the the sizing information. In addition it my opinion that M is far too course a measure and it introduces quite a bit of error in a number of the calculations that I routinely rely on.
>>
>> Kind regards,
>> Kirk
>>
>>> On Feb 1, 2016, at 11:18 AM, Bengt Rutisson <bengt.rutisson at oracle.com> wrote:
>>>
>>>
>>> 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