Seeking help regarding Full GCs with G1
Srini Padman
srini_was at yahoo.com
Thu Aug 7 14:54:15 UTC 2014
Thanks for both the suggestions, Wolfgang. We are going with the following parameters for the next test run:
-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=75 -XX:G1HeapWastePercent=5 -XX:InitiatingHeapOccupancyPercent=65 -XX:+UnlockDiagnosticVMOptions -XX:+G1PrintRegionLivenessInfo
The expectations being:
1\ with a total heap size of 4 GB, an application memory footprint of 2.2 GB, and an acceptable heap waste of 5%, the "effective" footprint is 2.2 + 0.05 * 4 GB = 2.4 GB, which is slightly smaller than 60% of the heap
2\ setting the initiating occupancy percent to 65% gives us a little bit of operating room over the effective heap footprint of 60%
3\ even if the heap is "perfectly" fragmented, that is, even if this means *all* regions are 60% occupied, all of them will still be eligible for mixed GCs since the threshold is now 75%.
Regards,
Srini.
On Thursday, August 7, 2014 9:02 AM, Wolfgang Pedot <wolfgang.pedot at finkzeit.at> wrote:
Hi again,
it might also help to to look at how the regions are occupied.
G1PrintRegionLivenessInfo will print the regions during the
marking-phase so you can see how many are OLD or possibly HUMS and how
they are occupied.
This information has helped me quite a bit while tweaking G1 and our
application for optimal performance.
regards
Wolfgang
Am 07.08.2014 00:48, schrieb Srini Padman:
> 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/20140807/a521da23/attachment-0001.html>
More information about the hotspot-gc-use
mailing list