There have been several minor complaints (from members of the Java performance team and early G1 adopters) about the information being emitted when PrintAdaptiveSizePolicy is enabled. Here are some examples:

From Simone Bordet:

...and I get this log, from time to time:

2012-11-05T12:09:02.422+0100: [GC pause (young) 2341.660: [G1Ergonomics (CSet Construction) start choosing CSet, predicted base time: 65.42 ms, remaining time: 134.58 ms, target pause time: 200.00 ms]
 2341.660: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 198 regions, survivors: 6 regions, predicted young region time: 27.03 ms]
 2341.660: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 198 regions, survivors: 6 regions, old: 0 regions, predicted pause time: 92.45 ms, target pause time: 200.00 ms]
 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 %)]
, 0.07907900 secs]

The relevant section is the last line, marked as G1Ergonomics (Heap Sizing).

Can someone shed a light on what it means ? Seems an attempt to expand, but calculates to 0 ?
I remember G1 has some "extra" allocation space that can be used beyond -Xmx, do I remember well ?

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