Mixed GC promotion issue
Wang, Yanping
yanping.wang at intel.com
Fri Apr 3 16:28:26 UTC 2015
Hi, Jenny
I can cover this issue by tuning G1 flags as you instructed. But I am wondering:
(1) how many engineers out there have the knowledge and willing to hand craft G1 with experimental G1 flags?
(2) Is this a G1 issue? If it is, for long run, why not fix it in G1 itself?
Below is another example: from same JVM version and same parameters:
Command Line flags: -XX:+UseG1GC -Xms80g -Xmx80g -XX:+AlwaysPreTouch -XX:G1HeapWastePercent=20 -XX:MaxGCPauseMillis=100 -XX:ParallelGCThreads=48 -XX:ConcGCThreads=32 -XX:+ParallelRefProcEnabled
Look at these two Mixed GCs: the first took 3.21 seconds to complete, with Heap: Heap: 76.6G(80.0G)->79.1G(80.0G)
That 76.6G is already 95.75% out of 80GB total heap. G1 has all the info it needs to decide and try to avoid Full-GC, but why does G1 still promote? Does G1 not know 79.1GB is so close to 80GB total heap side, and is guaranteed to have Full GC next?
The second Mixed GC took over 15 seconds to complete, followed up by a Full-GC that took over 27 seconds. In this Full-GC, we can see the heap: Heap: 80.0G(80.0G)->45.9G(80.0G)]. That means this workload's live data size is only around 46GB, and there is no humongous object allocation at all. Why did G1 still lost the race?
=====================================================
2015-03-12T21:08:01.385-0700: 16993.364: [GC pause (G1 Evacuation Pause) (mixed) 16993.364: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 57024, predicted base time: 53.85 ms, remaining time: 46.15 ms, target pause time: 100.00 ms]
16993.364: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 112 regions, survivors: 16 regions, predicted young region time: 59.86 ms]
16993.370: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: predicted time is too high, predicted time: 1.50 ms, remaining time: 0.00 ms, old: 239 regions, min: 239 regions]
16993.370: [G1Ergonomics (CSet Construction) added expensive regions to CSet, reason: old CSet region num not reached min, old: 239 regions, expensive: 239 regions, min: 239 regions, remaining time: 0.00 ms]
16993.370: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 112 regions, survivors: 16 regions, old: 239 regions, predicted pause time: 327.87 ms, target pause time: 100.00 ms]
16993.614: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: region allocation request failed, allocation request: 4317952 bytes]
16993.614: [G1Ergonomics (Heap Sizing) expand the heap, requested expansion amount: 4317952 bytes, attempted expansion amount: 33554432 bytes]
16993.614: [G1Ergonomics (Heap Sizing) did not expand the heap, reason: heap already fully expanded]
16996.219: [SoftReference, 0 refs, 0.0072010 secs]16996.227: [WeakReference, 82 refs, 0.0047163 secs]16996.231: [FinalReference, 4367 refs, 0.0427568 secs]16996.274: [PhantomReference, 0 refs, 21 refs, 0.0097792 secs]16996.284: [JNI Weak Reference, 0.0000225 secs] 16996.578: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 84355842048 bytes, allocation request: 0 bytes, threshold: 38654705655 bytes (45.00 %), source: end of GC]
16996.578: [G1Ergonomics (Mixed GCs) continue mixed GCs, reason: candidate old regions available, candidate old regions: 1667 regions, reclaimable: 19753877136 bytes (23.00 %), threshold: 20.00 %]
(to-space exhausted), 3.2139606 secs]
[Parallel Time: 2846.1 ms, GC Workers: 48]
[GC Worker Start (ms): Min: 16993370.6, Avg: 16993371.2, Max: 16993371.9, Diff: 1.3]
[Ext Root Scanning (ms): Min: 0.1, Avg: 0.6, Max: 1.4, Diff: 1.3, Sum: 31.1]
[Update RS (ms): Min: 8.6, Avg: 9.2, Max: 10.5, Diff: 1.9, Sum: 441.6]
[Processed Buffers: Min: 4, Avg: 7.5, Max: 13, Diff: 9, Sum: 361]
[Scan RS (ms): Min: 121.2, Avg: 122.0, Max: 122.9, Diff: 1.8, Sum: 5857.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): Min: 2709.2, Avg: 2710.5, Max: 2712.3, Diff: 3.1, Sum: 130104.8]
[Termination (ms): Min: 0.0, Avg: 1.4, Max: 2.1, Diff: 2.1, Sum: 69.1]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.1, Sum: 1.9]
[GC Worker Total (ms): Min: 2843.2, Avg: 2843.9, Max: 2844.5, Diff: 1.4, Sum: 136505.7]
[GC Worker End (ms): Min: 16996215.1, Avg: 16996215.1, Max: 16996215.2, Diff: 0.1]
[Code Root Fixup: 0.4 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 7.1 ms]
[Other: 360.4 ms]
[Evacuation Failure: 265.4 ms]
[Choose CSet: 6.1 ms]
[Ref Proc: 66.8 ms]
[Ref Enq: 3.2 ms]
[Redirty Cards: 11.5 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 6.7 ms]
[Eden: 3584.0M(3584.0M)->0.0B(3584.0M) Survivors: 512.0M->512.0M Heap: 76.6G(80.0G)->79.1G(80.0G)]
[Times: user=21.01 sys=1.04, real=3.21 secs]
2015-03-12T21:08:06.071-0700: 16998.050: [GC pause (G1 Evacuation Pause) (mixed) 16998.050: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 56280, predicted base time: 53.72 ms, remaining time: 46.28 ms, target pause time: 100.00 ms]
16998.050: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 30 regions, survivors: 16 regions, predicted young region time: 28.94 ms]
16998.060: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: reclaimable percentage not over threshold, old: 154 regions, max: 256 regions, reclaimable: 17164740528 bytes (19.98 %), threshold: 20.00 %]
16998.060: [G1Ergonomics (CSet Construction) added expensive regions to CSet, reason: old CSet region num not reached min, old: 154 regions, expensive: 143 regions, min: 239 regions, remaining time: 0.00 ms]
16998.060: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 30 regions, survivors: 16 regions, old: 154 regions, predicted pause time: 322.12 ms, target pause time: 100.00 ms]
16998.061: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: region allocation request failed, allocation request: 16777208 bytes]
16998.061: [G1Ergonomics (Heap Sizing) expand the heap, requested expansion amount: 16777208 bytes, attempted expansion amount: 33554432 bytes]
16998.061: [G1Ergonomics (Heap Sizing) did not expand the heap, reason: heap already fully expanded]
17012.741: [SoftReference, 0 refs, 0.0077200 secs]17012.749: [WeakReference, 0 refs, 0.0059451 secs]17012.755: [FinalReference, 0 refs, 0.0047808 secs]17012.760: [PhantomReference, 0 refs, 0 refs, 0.0117597 secs]17012.771: [JNI Weak Reference, 0.0000172 secs] 17013.701: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 85899345920 bytes, allocation request: 0 bytes, threshold: 38654705655 bytes (45.00 %), source: end of GC]
17013.701: [G1Ergonomics (Mixed GCs) do not continue mixed GCs, reason: reclaimable percentage not over threshold, candidate old regions: 1513 regions, reclaimable: 17164740528 bytes (19.98 %), threshold: 20.00 %]
(to-space exhausted), 15.6508656 secs]
[Parallel Time: 14676.7 ms, GC Workers: 48]
[GC Worker Start (ms): Min: 16998061.0, Avg: 16998061.6, Max: 16998062.1, Diff: 1.1]
[Ext Root Scanning (ms): Min: 0.2, Avg: 0.5, Max: 1.3, Diff: 1.1, Sum: 23.6]
[Update RS (ms): Min: 0.0, Avg: 6.4, Max: 12.7, Diff: 12.7, Sum: 306.5]
[Processed Buffers: Min: 0, Avg: 7.9, Max: 25, Diff: 25, Sum: 377]
[Scan RS (ms): Min: 112.8, Avg: 215.2, Max: 275.5, Diff: 162.8, Sum: 10331.2]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.3, Diff: 0.3, Sum: 0.7]
[Object Copy (ms): Min: 14384.2, Avg: 14451.0, Max: 14560.6, Diff: 176.4, Sum: 693647.4]
[Termination (ms): Min: 0.0, Avg: 1.0, Max: 1.8, Diff: 1.8, Sum: 47.7]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.9]
[GC Worker Total (ms): Min: 14673.6, Avg: 14674.1, Max: 14674.7, Diff: 1.1, Sum: 704358.0]
[GC Worker End (ms): Min: 17012735.7, Avg: 17012735.7, Max: 17012735.8, Diff: 0.1]
[Code Root Fixup: 0.5 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 5.9 ms]
[Other: 967.7 ms]
[Evacuation Failure: 894.2 ms]
[Choose CSet: 10.0 ms]
[Ref Proc: 33.2 ms]
[Ref Enq: 4.5 ms]
[Redirty Cards: 15.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 9.7 ms]
[Eden: 960.0M(3584.0M)->0.0B(4096.0M) Survivors: 512.0M->0.0B Heap: 80.0G(80.0G)->80.0G(80.0G)]
[Times: user=32.91 sys=5.11, real=15.64 secs]
a few Young GC with 80G heap later, Full-GC happened:
2015-03-12T21:08:22.363-0700: 17014.342: [Full GC (Allocation Failure) 17022.628: [SoftReference, 776 refs, 0.0001476 secs]17022.628: [WeakReference, 9010 refs, 0.0016977 secs]17022.630: [FinalReference, 3058 refs, 0.0016888 secs]17022.631: [PhantomReference, 0 refs, 2095 refs, 0.0002522 secs]17022.632: [JNI Weak Reference, 0.0000101 secs] 80G->45G(80G), 27.6925446 secs]
[Eden: 0.0B(4096.0M)->0.0B(4096.0M) Survivors: 0.0B->0.0B Heap: 80.0G(80.0G)->45.9G(80.0G)], [Metaspace: 49643K->49563K(51200K)]
[Times: user=58.11 sys=0.30, real=27.69 secs]
2015-03-12T21:08:50.057-0700: 17042.036: [GC concurrent-mark-abort]
===================================================
Thanks
-yanping
From: Yu Zhang [mailto:yu.zhang at oracle.com]
Sent: Friday, April 03, 2015 8:49 AM
To: Wang, Yanping; 'hotspot-gc-use at openjdk.java.net'
Subject: Re: Mixed GC promotion issue
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<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/20150403/06886e1d/attachment-0001.html>
More information about the hotspot-gc-use
mailing list