Seeking help regarding Full GCs with G1
Srini Padman
srini_was at yahoo.com
Mon Aug 25 17:03:08 UTC 2014
Hello Jenny/Wolfgang,
A quick note back to inform you that we started another round of tests with the following parameters, and things are looking very good so far (9 days into the test) - the patterns are very smooth, the footprint stabilized fairly early on, and there have been no Full GCS.
-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
We are hoping that the same trends will be continue once we go to production with these settings.
Thanks very much for the help!
Regards,
Srini.
On Thursday, August 7, 2014 10:54 AM, Srini Padman <srini_was at yahoo.com> wrote:
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/20140825/c4785dbe/attachment-0001.html>
More information about the hotspot-gc-use
mailing list