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

Tue Jun 10 01:29:39 UTC 2014

On 6/9/2014 6:03 PM, 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.
>
>
> Thanks. Do you mean InitiatingHeapOccupancyPercent=0 is disabling some 
> features? I thought it simply triggers the clean to start earlier 
> (always on). Will try different values, but would like to know what 
> harm =0 does?
By setting InitiatingHeapOccupancyPercent=0, you might have wasted the 
concurrent gc work.  Since when concurrent cycles are triggered, most of 
them are live objects.  The concurrent cycles have to go through all the 
objects, but can not clean them.  In your case, it might not be too bad, 
as the mixed gcs can clean ~1g of heap, and the cleanup can clean some, 
too.  But setting it to the right value should make g1 keeping up with 
the application, while not wasting too much work.

>     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 <tel: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.
>
>
> Thanks, will try that.
>
>     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
>
>
> It's a web application so response time is important for users, will 
> try 75 and GCPauseIntervalMillis=1000
>
>     " 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
>
>
> Will try that too.
>
>
>     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 16 cpus so I assume there are 16 threads...
Then setting it to 16 might not be a good idea. We usually do not want 
to use all the cpus.
>
>
>     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.
>
>
> Which are these? Do you mean gc logging being on might contribute to 
> something?
GC logging itself should not have much overhead.  IIRR, the cases were 
when there were logging activities from other processes, gc logging has 
to wait writing to log.
>
>
>>
>>     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.
>
>
> Has this been tried in some gc?
No.
>
> **
> Martin
>
>>
>>
>>     **
>>     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  <mailto: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/602114c8/attachment.html>