RFR(S): 8010780: G1: Eden occupancy/capacity output wrong after a full GC

[John Cuthbertson]

Hi Jon,

Thanks for looking over the changes.

JohnC

On 4/8/2013 3:16 PM, Jon Masamitsu wrote:
> Changes look good.
>
> Jon
>
> On 04/08/13 11:56, John Cuthbertson wrote:
>> Hi Everyone,
>>
>> Thomas Schatzl has reviewed these change (thanks Thomas!) so I'm 
>> looking for one additional reviewer. Any takers?
>>
>> Thanks,
>>
>> JohnC
>>
>> On 3/27/2013 3:12 PM, John Cuthbertson wrote:
>>> Hi Everyone,
>>>
>>> Can I have a couple of volunteers look review this fix? The webrev 
>>> can be found at: http://cr.openjdk.java.net/~johnc/8010780/webrev.0/
>>>
>>> Summary:
>>> One of the performance team spotted and error in the G1 logs 
>>> following a full GC:
>>>
>>> 411.322: [G1Ergonomics (Mixed GCs)  (to-space exhausted), 0.4279260 
>>> secs]
>>>   ....
>>>    [Eden: 0.0B(1840.0M)->0.0B(1840.0M) Survivors: 0.0B->0.0B Heap: 
>>> 36.0G(36.0G)->36.0G(36.0G)]
>>>  [Times: user=1.13 sys=0.10, real=0.43 secs]
>>>
>>> 411.336: [Full GC (Allocation Failure) 35G->18G(36G), 8.0471890 secs]
>>>  [Times: user=8.50 sys=0.01, real=8.05 secs]
>>>
>>> 433.639: [GC pause (G1 Evacuation Pause) (young) 433.640: 
>>> [G1Ergonomics (CSet Construction) start choosing CSet, 
>>> _pending_cards: 26203, predicted base time: 13.50 ms, remaining 
>>> time: 186.50 ms, target pause time: 200.00 ms]
>>>  433.640: [G1Ergonomics (CSet Construction) add young regions to 
>>> CSet, eden: 148 regions, survivors: 0 regions, predicted young 
>>> region time: 164.22 ms]
>>>  433.640: [G1Ergonomics (CSet Construction) finish choosing CSet, 
>>> eden: 148 regions, survivors: 0 regions, old: 0 regions, predicted 
>>> pause time: 177.72 ms, target pause time: 200.00 ms]
>>>
>>>  433.895: [G1Ergonomics (Concurrent Cycles) request concurrent cycle 
>>> initiation, reason: occupancy higher than threshold, occupancy: 
>>> 21458059264 bytes, allocation request: 0 bytes, threshold: 
>>> 17394617520 bytes (45.00 %), source: end of GC]
>>> , 0.2552910 secs]
>>> ....
>>>    [Eden: 2368.0M(1840.0M)->0.0B(1632.0M) Survivors: 0.0B->304.0M 
>>> Heap: 20.7G(36.0G)->20.2G(36.0G)]
>>>
>>> The heap transition line for the GC after the full GC was displaying 
>>> the eden capacity that was calculated by the GC preceding the full 
>>> GC rather than the eden capacity calculated at the end of the of the 
>>> full GC. As a result the reported eden occupancy is much larger than 
>>> the reported capacity.
>>>
>>> The main part of the fix is the moving of 
>>> G1CollectorPolicy::_prev_eden_capacity from 
>>> G1CollectorPolicy::print_detailed_heap_transition() to 
>>> G1CollectorPolicy::record_collection_pause_start(). The code that 
>>> records the heap state before the GC has been refactored into a 
>>> separate routine and is invoked at the start of both an incremental 
>>> and full GC.
>>>
>>> Additionally I added a more detailed heap transition message to the 
>>> full GC output:
>>>
>>>> 1.989: [Full GC (Allocation Failure) 256M->234M(256M), 2.3966795 secs]
>>>>    [Eden: 0.0B(12.0M)->0.0B(12.0M) Survivors: 0.0B->0.0B Heap: 
>>>> 256.0M(256.0M)->234.7M(256.0M)]
>>>>  [Times: user=3.00 sys=0.00, real=2.40 secs]
>>>>
>>>
>>> for validation purposes.
>>>
>>> Testing:
>>> GCOld with a small heap (128m) and +G1PrintHeapRegions
>>>
>>> Thanks,
>>>
>>> JohnC
>>>
>>