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

[John Cuthbertson]

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
>