Seeking help regarding Full GCs with G1
Srini Padman
srini_was at yahoo.com
Wed Aug 6 22:48:51 UTC 2014
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]
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20140806/93a5abf1/attachment.html>
More information about the hotspot-gc-use
mailing list