G1 log output interpretation

[John Cuthbertson]

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]

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?

Regards,

JohnC

On 11/5/2012 6:54 AM, Simone Bordet wrote:
> Hi,
>
> I am using 1.7.0_09 with:
>
> -XX:InitialHeapSize=1073741824
> -XX:MaxHeapSize=1073741824
> -XX:MaxPermSize=268435456
> -XX:ReservedCodeCacheSize=67108864
> -XX:InitiatingHeapOccupancyPercent=60
> -XX:MaxGCPauseMillis=200
> -XX:+PrintAdaptiveSizePolicy
> -XX:+PrintCommandLineFlags
> -XX:+PrintGCDateStamps
> -XX:+PrintGCDetails
> -XX:+UseCompressedOops
> -XX:+UseG1GC
>
> 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 ?
>
> 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
>
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20121107/5a300609/attachment.html