Seeking help regarding Full GCs with G1
Srini Padman
srini_was at yahoo.com
Thu Aug 7 02:17:15 UTC 2014
Ah, I see. I think that does explain the mystery.
The Oracle documentation only says this parameter "sets the occupancy threshold for an old region to be included in a mixed garbage collection cycle. The default occupancy is 65 percent." and I interpreted that as meaning a lower threshold rather than an upper threshold. It should have been obvious to me that the "Garbage First' collector, which aims to collect the "least live data first", will aim for an upper threshold, but yet I settled on exactly the wrong interpretation. Thanks for setting me right!
Knowing this, I now think that the default 10% G1HeapWastePercent value (which computes to 400 MB for us) and the application's footprint (~ 2.2 GB) *together* put our application at exactly the default occupancy threshold of 65% (2.6 GB). So we would have been operating in a configuration where no mixed GCs would ever be seen to be required. (Please correct me if that calculation is wrong.)
If we decrease G1HeapWastePercent to 5% and increase G1MixedGCLiveThresholdPercent to 75%, then the corresponding numbers would be (2.2 GB footprint + 200 MB waste < 3 GB) so we will be doing mixed GCs from 2.4 GB until we (roughly) hit 3 GB after which the chances of a Full GC increase again. So the hope in this case would be that enough heap is collected to never let the usage go above 3 GB (assuming, of course, that that means all regions are at equal occupancy of 75%). Am I understanding this correctly?
Also, what is the additional (performance) cost incurred because of setting the G1MixedGCLiveThresholdPercent value to 75%?
Thanks once again - due to my misunderstanding, I was really not sure what to do next!
Regards,
Srini.
On Wednesday, August 6, 2014 7:54 PM, Yu Zhang <yu.zhang at oracle.com> wrote:
Srini,
About -XX:G1MixedGCLiveThresholdPercent=65(default)
If the region's live data is above 65%, this region will not be
considered as a candidate.
In your case, you need to increase
-XX:G1MixedGCLiveThresholdPercent.
Thanks,
Jenny
On 8/6/2014 3:48 PM, Srini Padman wrote:
Hello,
>
>I am currently evaluating the use of the G1 Collector for our
application, to combat the fragmentation issues we ran into
while using the CMS collector (several cases of failed
promotions, followed by *really* long pauses). However, I am
also having trouble with tuning the G1 collector, and am
seeing behavior that I can't fully understand. I will
appreciate any help/insight that you guys can offer.
>
>What I find puzzling from looking at the G1 GC logs from our
tests is that the concurrent marking phase does not really
seem to identify many old regions to clean up at all, and the
heap usage keeps growing. At some point, there is no further
room to expand ("heap expansion operation failed") and this is
followed by a Full GC that lasts about 10 seconds. But the
Full GC actually brings the memory down by almost 50%, from
4095M to 2235M.
>
>If the Full GC can collect this much of the heap, I don't
fully understand why the concurrent mark phase does not
identify these (old?) regions for (mixed?) collection
subsequently.
>
>On the assumption that we should let the GC ergonomics do its
thing freely, I initially did not set any parameter other than
-Xmx, -Xms, and the PermGen sizes. I added the
G1HeapRegionSize and G1MixedGCLiveThresholdPercent settings
(see below) because, when I saw the Full GCs with the default
settings, I wondered whether we might be getting into a
situation where all (or most?) regions are roughly 65% live so
the concurrent marking phase does not identify them for
collection but a subsequent Full GC is able to. That is, I
wondered whether our application's heap footprint being 65% of
the max heap led to these full GCs coincidentally (since
G1MixedGCLiveThresholdPercent is 65% by default). But I don't
know why the same thing happens when I set
G1MixedGCLiveThresholdPercent down to 40% - even if all
regions are 40% full, we will only be at about 1.6 GB, and
that is far below what I think our heap footprint is in the
long run (2.2 GB). So I don't understand how to ensure that
old regions are cleaned up regularly so a Full GC is not
required.
>
>GC Settings in use:
>
>-server -Xms4096m -Xmx4096m -Xss512k -XX:PermSize=128m
-XX:MaxPermSize=128m -XX:+UseG1GC -XX:+ParallelRefProcEnabled
-XX:+DisableExplicitGC -verbose:gc
-XX:+PrintAdaptiveSizePolicy -XX:+UnlockExperimentalVMOptions
-XX:G1HeapRegionSize=2m -XX:G1MixedGCLiveThresholdPercent=40
>
>This is using JRE 1.7.0_55.
>
>I am including a short(ish) GC log snippet for the time
leading up to the Full GC. I can send the full GC log (about 8
MB, zipped) if necessary.
>
>Any help will be greatly appreciated!
>
>Regards,
>Srini.
>
>---------------------------
>
>2014-08-06T04:46:00.067-0700: 1124501.033: [GC
concurrent-root-region-scan-start]
>2014-08-06T04:46:00.081-0700: 1124501.047: [GC
concurrent-root-region-scan-end, 0.0139487 secs]
>2014-08-06T04:46:00.081-0700: 1124501.047: [GC
concurrent-mark-start]
>2014-08-06T04:46:10.531-0700: 1124511.514: [GC
concurrent-mark-end, 10.4675249 secs]
>2014-08-06T04:46:10.532-0700: 1124511.515: [GC remark
2014-08-06T04:46:10.532-0700: 1124511.516: [GC ref-proc,
0.0018819 secs], 0.0225253 secs]
> [Times: user=0.01 sys=0.00, real=0.02 secs]
>2014-08-06T04:46:10.555-0700: 1124511.539: [GC cleanup
3922M->3922M(4096M), 0.0098209 secs]
> [Times: user=0.03 sys=0.03, real=0.01 secs]
>2014-08-06T04:46:49.603-0700: 1124550.652: [GC pause (young)
>Desired survivor size 13631488 bytes, new threshold 15 (max
15)
>- age 1: 1531592 bytes, 1531592 total
>- age 2: 1087648 bytes, 2619240 total
>- age 3: 259480 bytes, 2878720 total
>- age 4: 493976 bytes, 3372696 total
>- age 5: 213472 bytes, 3586168 total
>- age 6: 186104 bytes, 3772272 total
>- age 7: 169832 bytes, 3942104 total
>- age 8: 201968 bytes, 4144072 total
>- age 9: 183752 bytes, 4327824 total
>- age 10: 136480 bytes, 4464304 total
>- age 11: 366208 bytes, 4830512 total
>- age 12: 137296 bytes, 4967808 total
>- age 13: 133592 bytes, 5101400 total
>- age 14: 162232 bytes, 5263632 total
>- age 15: 139984 bytes, 5403616 total
> 1124550.652: [G1Ergonomics (CSet Construction) start choosing
CSet, _pending_cards: 21647, predicted base time: 37.96 ms,
remaining time: 162.04 ms, target pause time: 200.00 ms]
> 1124550.652: [G1Ergonomics (CSet Construction) add young
regions to CSet, eden: 95 regions, survivors: 7 regions,
predicted young region time: 4.46 ms]
> 1124550.652: [G1Ergonomics (CSet Construction) finish
choosing CSet, eden: 95 regions, survivors: 7 regions, old: 0
regions, predicted pause time: 42.42 ms, target pause time:
200.00 ms]
> 1124550.701: [G1Ergonomics (Concurrent Cycles) do not request
concurrent cycle initiation, reason: still doing mixed
collections, occupancy: 4064280576 bytes, allocation request:
0 bytes, threshold: 1932735240 bytes (45.00 %), source: end of
GC]
> 1124550.701: [G1Ergonomics (Mixed GCs) start mixed GCs,
reason: candidate old regions available, candidate old
regions: 285 regions, reclaimable: 430117688 bytes (10.01 %),
threshold: 10.00 %]
>, 0.0494015 secs]
> [Parallel Time: 43.7 ms, GC Workers: 4]
> [GC Worker Start (ms): Min: 1124550651.8, Avg:
1124550668.7, Max: 1124550674.3, Diff: 22.6]
> [Ext Root Scanning (ms): Min: 0.1, Avg: 6.7, Max: 22.3,
Diff: 22.2, Sum: 26.8]
> [Update RS (ms): Min: 9.9, Avg: 11.0, Max: 12.3, Diff:
2.5, Sum: 44.0]
> [Processed Buffers: Min: 39, Avg: 40.3, Max: 41,
Diff: 2, Sum: 161]
> [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1,
Sum: 0.2]
> [Object Copy (ms): Min: 8.6, Avg: 8.9, Max: 9.6, Diff:
1.0, Sum: 35.6]
> [Termination (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff:
0.0, Sum: 0.3]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1,
Diff: 0.0, Sum: 0.2]
> [GC Worker Total (ms): Min: 21.1, Avg: 26.8, Max: 43.7,
Diff: 22.6, Sum: 107.1]
> [GC Worker End (ms): Min: 1124550695.4, Avg:
1124550695.5, Max: 1124550695.5, Diff: 0.0]
> [Code Root Fixup: 0.0 ms]
> [Clear CT: 0.1 ms]
> [Other: 5.6 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 4.5 ms]
> [Ref Enq: 0.1 ms]
> [Free CSet: 0.3 ms]
> [Eden: 190.0M(190.0M)->0.0B(190.0M) Survivors:
14.0M->14.0M Heap: 4077.0M(4096.0M)->3887.1M(4096.0M)]
> [Times: user=0.11 sys=0.00, real=0.05 secs]
>2014-08-06T04:47:45.545-0700: 1124606.686: [GC pause (mixed)
>Desired survivor size 13631488 bytes, new threshold 15 (max
15)
>- age 1: 1323232 bytes, 1323232 total
>- age 2: 716576 bytes, 2039808 total
>- age 3: 1058584 bytes, 3098392 total
>- age 4: 225208 bytes, 3323600 total
>- age 5: 447688 bytes, 3771288 total
>- age 6: 195112 bytes, 3966400 total
>- age 7: 178000 bytes, 4144400 total
>- age 8: 156904 bytes, 4301304 total
>- age 9: 193424 bytes, 4494728 total
>- age 10: 176272 bytes, 4671000 total
>- age 11: 134768 bytes, 4805768 total
>- age 12: 138896 bytes, 4944664 total
>- age 13: 132272 bytes, 5076936 total
>- age 14: 132856 bytes, 5209792 total
>- age 15: 161912 bytes, 5371704 total
> 1124606.686: [G1Ergonomics (CSet Construction) start choosing
CSet, _pending_cards: 20335, predicted base time: 38.61 ms,
remaining time: 161.39 ms, target pause time: 200.00 ms]
> 1124606.686: [G1Ergonomics (CSet Construction) add young
regions to CSet, eden: 95 regions, survivors: 7 regions,
predicted young region time: 4.53 ms]
> 1124606.686: [G1Ergonomics (CSet Construction) finish adding
old regions to CSet, reason: reclaimable percentage not over
threshold, old: 1 regions, max: 205 regions, reclaimable:
428818280 bytes (9.98 %), threshold: 10.00 %]
> 1124606.686: [G1Ergonomics (CSet Construction) finish
choosing CSet, eden: 95 regions, survivors: 7 regions, old: 1
regions, predicted pause time: 45.72 ms, target pause time:
200.00 ms]
> 1124606.731: [G1Ergonomics (Heap Sizing) attempt heap
expansion, reason: region allocation request failed,
allocation request: 1048576 bytes]
> 1124606.731: [G1Ergonomics (Heap Sizing) expand the heap,
requested expansion amount: 1048576 bytes, attempted expansion
amount: 2097152 bytes]
> 1124606.731: [G1Ergonomics (Heap Sizing) did not expand the
heap, reason: heap expansion operation failed]
> 1124606.743: [G1Ergonomics (Concurrent Cycles) do not request
concurrent cycle initiation, reason: still doing mixed
collections, occupancy: 4095737856 bytes, allocation request:
0 bytes, threshold: 1932735240 bytes (45.00 %), source: end of
GC]
> 1124606.743: [G1Ergonomics (Mixed GCs) do not continue mixed
GCs, reason: reclaimable percentage not over threshold,
candidate old regions: 284 regions, reclaimable: 428818280
bytes (9.98 %), threshold: 10.00 %]
> (to-space exhausted), 0.0568178 secs]
> [Parallel Time: 40.4 ms, GC Workers: 4]
> [GC Worker Start (ms): Min: 1124606686.1, Avg:
1124606701.7, Max: 1124606723.8, Diff: 37.7]
> [Ext Root Scanning (ms): Min: 0.1, Avg: 6.3, Max: 16.1,
Diff: 16.1, Sum: 25.4]
> [Update RS (ms): Min: 0.0, Avg: 9.6, Max: 13.3, Diff:
13.3, Sum: 38.6]
> [Processed Buffers: Min: 0, Avg: 37.5, Max: 52, Diff:
52, Sum: 150]
> [Scan RS (ms): Min: 0.0, Avg: 0.3, Max: 0.4, Diff: 0.4,
Sum: 1.1]
> [Object Copy (ms): Min: 2.6, Avg: 8.4, Max: 11.1, Diff:
8.5, Sum: 33.7]
> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff:
0.0, Sum: 0.0]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0,
Diff: 0.0, Sum: 0.1]
> [GC Worker Total (ms): Min: 2.7, Avg: 24.7, Max: 40.4,
Diff: 37.7, Sum: 98.9]
> [GC Worker End (ms): Min: 1124606726.5, Avg:
1124606726.5, Max: 1124606726.5, Diff: 0.0]
> [Code Root Fixup: 0.0 ms]
> [Clear CT: 0.1 ms]
> [Other: 16.3 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 7.7 ms]
> [Ref Enq: 0.2 ms]
> [Free CSet: 0.3 ms]
> [Eden: 190.0M(190.0M)->0.0B(188.0M) Survivors:
14.0M->16.0M Heap: 4077.1M(4096.0M)->3921.6M(4096.0M)]
> [Times: user=0.11 sys=0.00, real=0.06 secs]
>2014-08-06T04:49:57.698-0700: 1124739.058: [GC pause (young)
>Desired survivor size 13631488 bytes, new threshold 15 (max
15)
>- age 1: 1130192 bytes, 1130192 total
>- age 2: 492816 bytes, 1623008 total
>- age 3: 675240 bytes, 2298248 total
>- age 4: 1038536 bytes, 3336784 total
>- age 5: 208048 bytes, 3544832 total
>- age 6: 436520 bytes, 3981352 total
>- age 7: 184528 bytes, 4165880 total
>- age 8: 165376 bytes, 4331256 total
>- age 9: 154872 bytes, 4486128 total
>- age 10: 179016 bytes, 4665144 total
>- age 11: 167760 bytes, 4832904 total
>- age 12: 132056 bytes, 4964960 total
>- age 13: 138736 bytes, 5103696 total
>- age 14: 132080 bytes, 5235776 total
>- age 15: 132856 bytes, 5368632 total
> 1124739.058: [G1Ergonomics (CSet Construction) start choosing
CSet, _pending_cards: 44501, predicted base time: 51.94 ms,
remaining time: 148.06 ms, target pause time: 200.00 ms]
> 1124739.058: [G1Ergonomics (CSet Construction) add young
regions to CSet, eden: 87 regions, survivors: 8 regions,
predicted young region time: 4.37 ms]
> 1124739.058: [G1Ergonomics (CSet Construction) finish
choosing CSet, eden: 87 regions, survivors: 8 regions, old: 0
regions, predicted pause time: 56.32 ms, target pause time:
200.00 ms]
> 1124739.060: [G1Ergonomics (Heap Sizing) attempt heap
expansion, reason: region allocation request failed,
allocation request: 1048576 bytes]
> 1124739.060: [G1Ergonomics (Heap Sizing) expand the heap,
requested expansion amount: 1048576 bytes, attempted expansion
amount: 2097152 bytes]
> 1124739.060: [G1Ergonomics (Heap Sizing) did not expand the
heap, reason: heap expansion operation failed]
> 1124739.252: [G1Ergonomics (Concurrent Cycles) request
concurrent cycle initiation, reason: occupancy higher than
threshold, occupancy: 4294967296 bytes, allocation request: 0
bytes, threshold: 1932735240 bytes (45.00 %), source: end of
GC]
> (to-space exhausted), 0.1936102 secs]
> [Parallel Time: 146.6 ms, GC Workers: 4]
> [GC Worker Start (ms): Min: 1124739058.5, Avg:
1124739061.6, Max: 1124739063.0, Diff: 4.4]
> [Ext Root Scanning (ms): Min: 0.2, Avg: 7.0, Max: 14.3,
Diff: 14.0, Sum: 28.2]
> [Update RS (ms): Min: 4.8, Avg: 10.7, Max: 17.6, Diff:
12.8, Sum: 42.7]
> [Processed Buffers: Min: 47, Avg: 56.3, Max: 69,
Diff: 22, Sum: 225]
> [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0,
Sum: 0.2]
> [Object Copy (ms): Min: 113.1, Avg: 125.6, Max: 137.6,
Diff: 24.5, Sum: 502.5]
> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff:
0.1, Sum: 0.2]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0,
Diff: 0.0, Sum: 0.1]
> [GC Worker Total (ms): Min: 142.1, Avg: 143.5, Max:
146.5, Diff: 4.4, Sum: 573.8]
> [GC Worker End (ms): Min: 1124739205.1, Avg:
1124739205.1, Max: 1124739205.1, Diff: 0.0]
> [Code Root Fixup: 0.0 ms]
> [Clear CT: 0.1 ms]
> [Other: 46.9 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 1.0 ms]
> [Ref Enq: 0.1 ms]
> [Free CSet: 0.2 ms]
> [Eden: 174.0M(188.0M)->0.0B(204.0M) Survivors:
16.0M->0.0B Heap: 4095.6M(4096.0M)->4095.6M(4096.0M)]
> [Times: user=0.36 sys=0.00, real=0.19 secs]
> 1124739.259: [G1Ergonomics (Concurrent Cycles) initiate
concurrent cycle, reason: concurrent cycle initiation
requested]
>2014-08-06T04:49:57.898-0700: 1124739.259: [GC pause (young)
(initial-mark)
>Desired survivor size 13631488 bytes, new threshold 15 (max
15)
> 1124739.259: [G1Ergonomics (CSet Construction) start choosing
CSet, _pending_cards: 322560, predicted base time: 205.33 ms,
remaining time: 0.00 ms, target pause time: 200.00 ms]
> 1124739.259: [G1Ergonomics (CSet Construction) add young
regions to CSet, eden: 0 regions, survivors: 0 regions,
predicted young region time: 0.00 ms]
> 1124739.259: [G1Ergonomics (CSet Construction) finish
choosing CSet, eden: 0 regions, survivors: 0 regions, old: 0
regions, predicted pause time: 205.33 ms, target pause time:
200.00 ms]
>, 0.0347198 secs]
> [Parallel Time: 33.1 ms, GC Workers: 4]
> [GC Worker Start (ms): Min: 1124739259.3, Avg:
1124739259.3, Max: 1124739259.3, Diff: 0.0]
> [Ext Root Scanning (ms): Min: 5.5, Avg: 7.7, Max: 11.0,
Diff: 5.4, Sum: 30.6]
> [Update RS (ms): Min: 18.4, Avg: 19.8, Max: 20.6, Diff:
2.2, Sum: 79.4]
> [Processed Buffers: Min: 293, Avg: 315.3, Max: 350,
Diff: 57, Sum: 1261]
> [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0,
Sum: 0.0]
> [Object Copy (ms): Min: 1.6, Avg: 5.4, Max: 6.9, Diff:
5.3, Sum: 21.7]
> [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff:
0.1, Sum: 0.4]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0,
Diff: 0.0, Sum: 0.1]
> [GC Worker Total (ms): Min: 33.0, Avg: 33.0, Max: 33.1,
Diff: 0.1, Sum: 132.1]
> [GC Worker End (ms): Min: 1124739292.3, Avg:
1124739292.3, Max: 1124739292.3, Diff: 0.0]
> [Code Root Fixup: 0.0 ms]
> [Clear CT: 0.1 ms]
> [Other: 1.5 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 1.0 ms]
> [Ref Enq: 0.1 ms]
> [Free CSet: 0.0 ms]
> [Eden: 0.0B(204.0M)->0.0B(204.0M) Survivors:
0.0B->0.0B Heap: 4095.6M(4096.0M)->4095.6M(4096.0M)]
> [Times: user=0.12 sys=0.00, real=0.04 secs]
>2014-08-06T04:49:57.933-0700: 1124739.294: [GC
concurrent-root-region-scan-start]
>2014-08-06T04:49:57.933-0700: 1124739.294: [GC
concurrent-root-region-scan-end, 0.0000157 secs]
>2014-08-06T04:49:57.933-0700: 1124739.294: [GC
concurrent-mark-start]
> 1124739.295: [G1Ergonomics (Heap Sizing) attempt heap
expansion, reason: allocation request failed, allocation
request: 80 bytes]
> 1124739.295: [G1Ergonomics (Heap Sizing) expand the heap,
requested expansion amount: 2097152 bytes, attempted expansion
amount: 2097152 bytes]
> 1124739.295: [G1Ergonomics (Heap Sizing) did not expand the
heap, reason: heap expansion operation failed]
>2014-08-06T04:49:57.934-0700: 1124739.295: [Full GC
4095M->2235M(4096M), 10.5341003 secs]
> [Eden: 0.0B(204.0M)->0.0B(1436.0M) Survivors:
0.0B->0.0B Heap: 4095.6M(4096.0M)->2235.4M(4096.0M)]
> [Times: user=13.20 sys=0.03, real=10.52 secs]
>
>
>
>
>
>
>_______________________________________________
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/20140806/3dd890d3/attachment-0001.html>
More information about the hotspot-gc-use
mailing list