Mixed GC promotion issue

Fri Apr 3 05:29:55 UTC 2015

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

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20150403/5d8481a1/attachment-0001.html>