G1 log output interpretation

[John Cuthbertson]

Hi Simone,

Apologies. For some reason this ended up in my junk email folder (and 
no, it wasn't deliberate) :-) .

I've submitted: JDK-8003731 - G1: Improve PrintAdaptiveSizePolicy 
(ErgoVerbose) output. <https://jbs.oracle.com/bugs/browse/JDK-8003731>

to track your issues with the ErgoVerbose output.

I'll try to answer your questions inline....

On 11/07/12 14:34, Simone Bordet wrote:
>>  24.941: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent
>> GC overhead higher than threshold after GC, recent GC overhead: 11.23 %,
>> threshold: 10.00 %]
>>  24.941: [G1Ergonomics (Heap Sizing) uncommitted: 2097152 bytes, min
>> expansion amount: 2097152 bytes, max expansion amount: 2097152 bytes]
>>  24.941: [G1Ergonomics (Heap Sizing) calculated expansion amount: 419430
>> bytes (20.00 %), actual expansion amount: 2097152 bytes]
>>     
>
> I'd still be confused by this line, where the calculated expansion
> amount is different from the actual expansion amount...
> My problem was in the interpretation of "uncommitted", which I did not
> fully understand (my fault).
>
>   

When G1 expands the heap it needs to round the calculated (or desired) 
expansion amount (based upon the percentage flag) up to a multiple of 
heap region size. In the example above the calculated amount was much 
less than the region size (2mb). Unfortunately we can't expand the heap 
by a fraction of a region.

>> Then:
>>   24.941: [G1Ergonomics (Heap Sizing) expand the heap, requested expansion
>> amount: 2097152 bytes, attempted expansion amount: 2097152 bytes]
>>
>> Then:
>>   24.941: [G1Ergonomics (Heap Sizing) heap expansion {passed | failed},
>> capacity before: XXXXX bytes, capacity after: XXXXX bytes]
>>
>> Would that clear up any confusion?
>>     
>
> Clearer, yes.
>
> While we're at it, may I also ask about this other output:
>
> [from the previous young GC just after a concurrent marking ended]
>  29235.349: [G1Ergonomics (Mixed GCs) start mixed GCs, reason:
> candidate old regions available, candidate old regions: 184 regions,
> reclaimable: 91408328 bytes (8.51 %), threshold: 1.00 %]
>    [Eden: 192M(191M)->0B(198M) Survivors: 13M->6144K Heap:
> 520M(1024M)->321M(1024M)]
>  [Times: user=0.17 sys=0.00, real=0.11 secs]
>
> 2012-11-07T19:32:49.391+0100: [GC pause (mixed) 29255.887:
> [G1Ergonomics (CSet Construction) start choosing CSet, predicted base
> time: 89.44 ms, remaining time: 110.56 ms, target pause time: 200.00
> ms]
>  29255.887: [G1Ergonomics (CSet Construction) add young regions to
> CSet, eden: 198 regions, survivors: 6 regions, predicted young region
> time: 78.11 ms]
>  29255.888: [G1Ergonomics (CSet Construction) finish adding old
> regions to CSet, reason: predicted time is too high, predicted time:
> 1.54 ms, remaining time: -5.19 ms, old: 46 regions, min: 46 regions]
>  29255.888: [G1Ergonomics (CSet Construction) added expensive regions
> to CSet, reason: old CSet region num not reached min, old: 46 regions,
> expensive: 4 regions, min: 46 regions, remaining time: -5.19 ms]
>  29255.888: [G1Ergonomics (CSet Construction) finish choosing CSet,
> eden: 198 regions, survivors: 6 regions, old: 46 regions, predicted
> pause time: 205.19 ms, target pause time: 200.00 ms]
> , 0.14591800 secs]
> ...
>  29256.034: [G1Ergonomics (Mixed GCs) continue mixed GCs, reason:
> candidate old regions available, candidate old regions: 138 regions,
> reclaimable: 48771256 bytes (4.54 %), threshold: 1.00 %]
>    [Eden: 198M(198M)->0B(197M) Survivors: 6144K->7168K Heap:
> 519M(1024M)->281M(1024M)]
>  [Times: user=0.22 sys=0.00, real=0.15 secs]
>
> In particular, what is the exact meaning of "expensive" and why there
> are all these negative times, and why a predicted time of 1.54 ms is
> too high.
>   

We predict how long it will take to collect an old region based upon the 
amount of live data that has to be evacuated, the size of the region's 
remembered set, and a couple of other terms that we track. This yields 
the predicted time for a region. When we're determining which old 
regions to add to the collection set we keep track of how much time we 
have left (against the pause time goal) after subtracted the sum of the 
predicted collection times for the regions already in the collection 
set. A region that is too expensive is one whose predicted time doesn't 
fit in the time remaining.

At the end of marking we sort the candidate old regions based upon the 
ratio of live data vs predicted collection time (i.e. a measure of the 
GC efficiency) and we try to collect the old regions with the most "bang 
for the buck" early in the mixed GC phase.

As you have seen in your logs, the prediction code gets it wrong. I 
think we're over predicting young regions and under predicting old 
regions. I'm hoping to fix that.
> I also noticed that after a concurrent marking ends, there is always a
> young GC (not a mixed one), followed by the 4 mixed GC.
> So the first GC after the concurrent marking is never a mixed GC, but
> always a young GC. Is this normal behavior ?
>
>   

Yes it is. The first GC after marking completed had it's eden sized 
before marking completed and so it is sized based upon expecting to 
collect only young regions. Adding some old regions to this collection 
set could exceed the goal.

Hope this helps.

JohnC
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20121120/8e671033/attachment.html