G1 log output interpretation

[Simone Bordet]

Hi,

On Wed, Nov 7, 2012 at 6:24 PM, John Cuthbertson
<john.cuthbertson at oracle.com> wrote:
> Hi Simone,
>
> Monica asked the same thing recently. The message:
>
>
> 2341.739: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent
> GC overhead higher than threshold after GC, recent GC overhead: 11.81 %,
> threshold: 10.00 %, uncommitted: 0 bytes, calculated expansion amount: 0
> bytes (20.00 %)]
>
> indicates that we would like to expand the heap because the current GC
> overhead to date (11.81%) is larger than the desired threshold (10%)...but
> the amount of uncommitted bytes left in the heap is 0 and we can't really
> expand the heap and we don't actually perform the attempt. If an actual
> expansion attempt was attempted there would another message similar to:
>
> 24.941: [G1Ergonomics (Heap Sizing) expand the heap, requested expansion
> amount: 1048576 bytes, attempted expansion amount: 2097152 bytes]
>
> A way of interpreting this message is should we attempt to expand the heap
> and by how much (based upon the percentage of the uncommitted space - 20%)
>
> One issue I see in the code that we can and should make the min expansion
> amount in expansion_amount() be MAX(1*M, RegionSize).  A new format could
> be:
>
>  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).

> 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.
The logs seems to hint that there are expensive and cheap old regions,
that a decision has been made about how many of either include in the
mixed GC, but it's not clear why the last line always report all old
regions.
Also, the message "added expensive regions to CSet, old CSet region
num not reached min, old: 46 regions, expensive: 4 regions, min: 46
regions" seems to hint that a minimum has not been reached, yet it
says the minimum is 46 so it *has* been reached.

I understand that after the concurrent marking, 186 old regions have
been detected to be candidate for collection.
Since G1 uses 4 mixed GC, 186/4=46.5 regions per collection.
On this GC, 46 regions have been selected, of which 4 are "expensive"
(in the next 3 mixed GCs, all 46 regions are "expensive").
Am I guessing right ?

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 ?

Thanks !

Simon
--
http://cometd.org
http://webtide.com
Developer advice, training, services and support
from the Jetty & CometD experts.
----
Finally, no matter how good the architecture and design are,
to deliver bug-free software with optimal performance and reliability,
the implementation technique must be flawless.   Victoria Livschitz