Why does G1GC do Full GC when it only needs 40 bytes?

[YU ZHANG]

Thanks for the log.  Please see my comments in line

Thanks,
Jenny

On 6/9/2014 7:29 AM, Martin Makundi wrote:
> 1. "-XX:InitiatingHeapOccupancyPercent=0 should trigger concurrent gcs 
> too much. "
>
> We use InitiatingHeapOccupancyPercent to make sure the gc is always 
> active. How is InitiatingHeapOccupancyPercent related to Full GC:s?
InitiatingHeapOccupancyPercentdetermines when concurrent gcs are 
triggered, so that we can do mixed gc.  In your case,the heap usage 
after full gc is 15.5g, you can try to set this to 60.

But this is not the reason why you get full gcs.

The mixed gc should be able to clean more.
In the gc log, there are a lot of messages like:
1. "750.559: [G1Ergonomics (CSet Construction) finish adding old regions 
to CSet, reason: reclaimable percentage not over threshold, old: 38 
regions, max: 379 regions, reclaimable: 3172139640 bytes (9.99 %), 
threshold: 10.00 %]"

the 10% threshold is controlled by -XX:G1HeapWastePercent=10.  You can 
try 5% so that more mixed gcs will happen after the concurrent cycles.

2. Depending on if target pause time =500 is critical.
Currently, the gc pause is > 500ms.  If keeping gc pause <500 is 
critical, you need to decrease Eden size.
We need to take another look at the gc logs then.

If you can relax the target pause time, please increase it, so that we 
do not see too many
" 5099.012: [G1Ergonomics (CSet Construction) finish adding old regions 
to CSet, reason: predicted time is too high, predicted time: 3.34 ms, 
remaining time: 0.00 ms, old: 100 regions, min: 100 regions]", maybe 
even to try,  -XX:G1MixedGCCountTarget=<4>. This determines the minimum 
old regions added to CSet

This workload has high reference process time.  It is good that you have 
enabled parallel reference processing.   It seems the parallel work is 
distributed among the 13 gc threads well.  Though the work termination 
time is high.  If you are not cpu bound, you can try to increase the gc 
threads to 16 using -XX:ParallelGCThreads=16, ASSUMING you are not cpu 
bound, your system has 20-cpu threads?

There are a lot of system cpu activities, which might contribute to 
longer gc pause.  I used to see people reported this is due to logging.  
Not sure if this applies to your case.
>
> 2. "What is the jdk version?
>
> java version "1.7.0_55"
> Java(TM) SE Runtime Environment (build 1.7.0_55-b13)
> Java HotSpot(TM) 64-Bit Server VM (build 24.55-b03, mixed mode)
>
>
> 3. Can you share the gc log?"
>
> Log is available at 81.22.250.165/log <http://81.22.250.165/log>
>
> 4. I wonder if it is possible to have mixed set of 
> different/automatically varying  sizes of G1HeapRegionSize's small for 
> smaller objects and larger for larger objects?
Currently we do not have mixed region size.
>
>
> **
> Martin
>
>
> 2014-06-07 11:03 GMT+03:00 Martin Makundi 
> <martin.makundi at koodaripalvelut.com 
> <mailto:martin.makundi at koodaripalvelut.com>>:
>
>     Why does G1GC do Full GC when it only needs only 40 bytes?
>
>     Is there a way to tune this so that it would try to free up "some"
>     chunk of memory and escape the full gc when enough memory has been
>     freed? This  would lower the freeze time?
>
>     See logs:
>
>      [Times: user=12.89 sys=0.16, real=1.25 secs]
>     2014-06-06T17:11:48.727+0300: 34022.631: [GC
>     concurrent-root-region-scan-start]
>     2014-06-06T17:11:48.727+0300: 34022.631: [GC
>     concurrent-root-region-scan-end, 0.0000180 secs]
>     2014-06-06T17:11:48.727+0300: 34022.631: [GC concurrent-mark-start]
>      34022.632: [G1Ergonomics (Heap Sizing) attempt heap expansion,
>     reason: allocation request failed, allocation request: 40 bytes]
>      34022.632: [G1Ergonomics (Heap Sizing) expand the heap, requested
>     expansion amount: 8388608 bytes, attempted expansion amount:
>     8388608 bytes]
>      34022.632: [G1Ergonomics (Heap Sizing) did not expand the heap,
>     reason: heap expansion operation failed]
>     {Heap before GC invocations=1867 (full 1):
>      garbage-first heap   total 31457280K, used 31453781K
>     [0x00007f1724000000, 0x00007f1ea4000000, 0x00007f1ea4000000)
>       region size 8192K, 0 young (0K), 0 survivors (0K)
>      compacting perm gen  total 524288K, used 166271K
>     [0x00007f1ea4000000, 0x00007f1ec4000000, 0x00007f1ec4000000)
>        the space 524288K,  31% used [0x00007f1ea4000000,
>     0x00007f1eae25fdc8, 0x00007f1eae25fe00, 0x00007f1ec4000000)
>     No shared spaces configured.
>     2014-06-06T17:11:48.728+0300: 34022.632: [Full GC 29G->13G(30G),
>     47.7918670 secs]
>
>
>     Settings:
>
>     -server -XX:InitiatingHeapOccupancyPercent=0 -Xss4096k
>     -XX:MaxPermSize=512m -XX:PermSize=512m -Xms20G -Xmx30G -Xnoclassgc
>     -XX:-OmitStackTraceInFastThrow -XX:+UseNUMA
>     -XX:+UseFastAccessorMethods -XX:ReservedCodeCacheSize=128m
>     -XX:-UseStringCache -XX:+UseGCOverheadLimit -Duser.timezone=EET
>     -XX:+UseCompressedOops -XX:+DisableExplicitGC -XX:+AggressiveOpts
>     -XX:CMSInitiatingOccupancyFraction=70 -XX:+ParallelRefProcEnabled
>     -XX:+UseAdaptiveSizePolicy -XX:MaxGCPauseMillis=500 -XX:+UseG1GC
>     -XX:G1HeapRegionSize=8M -XX:GCPauseIntervalMillis=10000
>     -XX:+PrintGCDetails -XX:+PrintHeapAtGC
>     -XX:+PrintAdaptiveSizePolicy -XX:+PrintGCDateStamps -XX:+PrintGC
>     -Xloggc:gc.log
>
>
>
>
> _______________________________________________
> 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/20140609/34eab789/attachment.html>