Mixed GC promotion issue

Fri Apr 3 15:49:13 UTC 2015

Yanping,

you can try 2 things:
-XX:+UnlockExperimentalVMOptions -XX:G1NewSizePercent=1   The default 
NewSizePercent is 5, which might be too high for big heap.
in crease
*-XX:G1MixedGCCountTarget=<8>
*to reduce the  number of expensive regions added to cset.

Thanks,
Jenny

On 4/2/2015 10:29 PM, Wang, Yanping wrote:
>
> Hi,
>
> I have a GC log from 8 nodes cluster running 90% write and 10% Read 
> YCSB to test HBase performance.
>
> JVM version: Java HotSpot(TM) 64-Bit Server VM (25.40-b25) for 
> linux-amd64 JRE (1.8.0_40-b25), built on Feb 10 2015 21:29:53 by 
> "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
>
> Command Line flags: -XX:+UseG1GC –Xms80g –Xmx80g -XX:+AlwaysPreTouch 
> -XX:G1HeapWastePercent=20 -XX:MaxGCPauseMillis=100 
> -XX:ParallelGCThreads=48 -XX:ConcGCThreads=32 -XX:+ParallelRefProcEnabled
>
> The run had 2 Full GCs with GC pause 27 seconds and 23 seconds, which 
> is pretty bad for latency sensitive HBase.
>
> I looked at the log and found: before both Full GCs, there were Mixed 
> GC did some sort of size promotion, regardless heap usage was already 
> over 90%.
>
> See attached one of the case below, this Mixed GC pause only took 0.57 
> seconds, but heap got 75.8G(80.0G)->78.5G(80.0G)]
>
> After that, the next Mixed GC hit “to-space exhausted” with 19 seconds 
> pause, followed by Full GC that took 23 seconds.
>
> I am wondering why G1 still decided to promote size up from 75.8G with 
> 80GB heap? Is it possible to decide don’t promote if heap occupancy is 
> already over 85%? Or 90%?
>
> =======================================================
>
> 2015-03-12T21:12:51.326-0700: 17283.305: [GC pause (G1 Evacuation 
> Pause) (mixed) 17283.305: [G1Ergonomics (CSet Construction) start 
> choosing CSet, _pending_cards: 65985, predicted base time: 51.83 ms, 
> remaining time: 48.17 ms, target pause time: 100.00 ms]
>
> 17283.305: [G1Ergonomics (CSet Construction) add young regions to 
> CSet, eden: 112 regions, survivors: 16 regions, predicted young region 
> time: 60.86 ms]
>
> 17283.307: [G1Ergonomics (CSet Construction) finish adding old regions 
> to CSet, reason: predicted time is too high, predicted time: 0.97 ms, 
> remaining time: 0.00 ms, old: 242 regions, min: 242 regions]
>
> 17283.307: [G1Ergonomics (CSet Construction) added expensive regions 
> to CSet, reason: old CSet region num not reached min, old: 242 
> regions, expensive: 242 regions, min: 242 regions, remaining time: 
> 0.00 ms]
>
> 17283.307: [G1Ergonomics (CSet Construction) finish choosing CSet, 
> eden: 112 regions, survivors: 16 regions, old: 242 regions, predicted 
> pause time: 249.13 ms, target pause time: 100.00 ms]
>
> 17283.500: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: 
> region allocation request failed, allocation request: 8870968 bytes]
>
> 17283.501: [G1Ergonomics (Heap Sizing) expand the heap, requested 
> expansion amount: 8870968 bytes, attempted expansion amount: 33554432 
> bytes]
>
> 17283.501: [G1Ergonomics (Heap Sizing) did not expand the heap, 
> reason: heap already fully expanded]
>
> 17283.723: [SoftReference, 0 refs, 0.0029074 secs]17283.726: 
> [WeakReference, 53 refs, 0.0013187 secs]17283.727: [FinalReference, 
> 2758 refs, 0.0186603 secs]17283.746: [PhantomReference, 0 refs, 20 
> refs, 0.0054745 secs]17283.752: [JNI Weak Reference, 0.0000076 secs] 
> 17283.880: [G1Ergonomics (Concurrent Cycles) do not request concurrent 
> cycle initiation, reason: still doing mixed collections, occupancy: 
> 84087406592 bytes, allocation request: 0 bytes, threshold: 38654705655 
> bytes (45.00 %), source: end of GC]
>
> 17283.881: [G1Ergonomics (Mixed GCs) continue mixed GCs, reason: 
> candidate old regions available, candidate old regions: 1692 regions, 
> reclaimable: 21320699264 bytes (24.82 %), threshold: 20.00 %]
>
> (to-space exhausted), 0.5759340 secs]
>
>    [Parallel Time: 414.1 ms, GC Workers: 48]
>
>       [GC Worker Start (ms): Min: 17283307.7, Avg: 17283309.1, Max: 
> 17283309.9, Diff: 2.2]
>
>       [Ext Root Scanning (ms): Min: 0.0, Avg: 0.4, Max: 1.7, Diff: 
> 1.7, Sum: 18.4]
>
>       [Update RS (ms): Min: 9.2, Avg: 9.9, Max: 11.7, Diff: 2.5, Sum: 
> 474.6]
>
>          [Processed Buffers: Min: 5, Avg: 8.1, Max: 15, Diff: 10, Sum: 
> 391]
>
>       [Scan RS (ms): Min: 62.5, Avg: 64.8, Max: 72.5, Diff: 9.9, Sum: 
> 3111.1]
>
>       [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 
> 0.0, Sum: 0.1]
>
>       [Object Copy (ms): Min: 328.9, Avg: 336.6, Max: 337.9, Diff: 
> 9.0, Sum: 16156.0]
>
>       [Termination (ms): Min: 0.0, Avg: 0.4, Max: 0.7, Diff: 0.7, Sum: 
> 19.6]
>
>       [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, 
> Sum: 3.2]
>
>       [GC Worker Total (ms): Min: 411.2, Avg: 412.1, Max: 413.5, Diff: 
> 2.2, Sum: 19782.8]
>
>       [GC Worker End (ms): Min: 17283721.2, Avg: 17283721.2, Max: 
> 17283721.3, Diff: 0.2]
>
>    [Code Root Fixup: 0.2 ms]
>
>    [Code Root Purge: 0.0 ms]
>
>    [Clear CT: 5.6 ms]
>
>    [Other: 156.1 ms]
>
>       [Evacuation Failure: 108.7 ms]
>
>       [Choose CSet: 2.5 ms]
>
>       [Ref Proc: 29.6 ms]
>
>       [Ref Enq: 2.2 ms]
>
>       [Redirty Cards: 9.0 ms]
>
>       [Humongous Reclaim: 0.0 ms]
>
>       [Free CSet: 3.4 ms]
>
>    [Eden: 3584.0M(3584.0M)->0.0B(3584.0M) Survivors: 512.0M->512.0M 
> Heap: 75.8G(80.0G)->78.5G(80.0G)]
>
> [Times: user=14.41 sys=0.16, real=0.57 secs]
>
> ====================================================
>
> Thanks
>
> -yanping
>
>
>
> _______________________________________________
> 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/20150403/a22b338b/attachment.html>