G1 GC clean up time is too long
YU ZHANG
yu.zhang at oracle.com
Thu Jan 2 08:24:59 PST 2014
Yao,
Thanks for the feedback. Glad to know that the tuning helps.
We are working on improving G1 performance. If the current build does
not meet your requirements, I hope the future builds(jdk8), with more
improvements, work for your workload.
Thanks,
Jenny
On 12/31/2013 5:27 PM, yao wrote:
> Hi Folks,
>
> Sorry for reporting GC performance result late, we are in the code
> freeze period for the holiday season and cannot do any production
> related deployment.
>
> First, I'd like to say thank you to Jenny, Monica and Thomas. Your
> suggestions are really helpful and help us to understand G1 GC
> behavior. We did NOT observe any full GCs after adjusting suggested
> parameters. That is really awesome, we tried these new parameters on
> Dec 26 and full GC disappeared since then (at least until I am writing
> this email, at 3:37pm EST, Dec 30).
>
> G1 parameters:
> *-XX:MaxGCPauseMillis=100
> *-XX:G1HeapRegionSize=32m
> *-XX:InitiatingHeapOccupancyPercent=65
> *-XX:G1ReservePercent=20
> *-XX:G1HeapWastePercent=5
> -XX:G1MixedGCLiveThresholdPercent=75
>
> *
> We've reduced**MaxGCPauseMillis to 100 since our real-time system is
> focus on low pause, if system cannot give response in 50 milliseconds,
> it's totally useless for the client. However, current read latency 99
> percentile is still slightly higher than CMS machines but they are
> pretty close (14 millis vs 12 millis). One thing we can do now is to
> increase heap size for G1 machines, for now, the heap size for G1 is
> only 90 percent of those CMS machines. This is because we observed our
> server process is killed by OOM killer on G1 machines and we decided
> to decrease heap size on G1 machines. Since G1ReservePercent was
> increased, we think it should be safe to increase G1 heap to be same
> as CMS machine. We believe it could make G1 machine give us better
> performance because 40 percent of heap will be used for block cache.
>
> Thanks
> -Shengzhe
>
> G1 Logs
>
> 2013-12-30T08:25:26.727-0500: 308692.158: [GC pause (young)
> Desired survivor size 234881024 bytes, new threshold 14 (max 15)
> - age 1: 16447904 bytes, 16447904 total
> - age 2: 30614384 bytes, 47062288 total
> - age 3: 16122104 bytes, 63184392 total
> - age 4: 16542280 bytes, 79726672 total
> - age 5: 14249520 bytes, 93976192 total
> - age 6: 15187728 bytes, 109163920 total
> - age 7: 15073808 bytes, 124237728 total
> - age 8: 17903552 bytes, 142141280 total
> - age 9: 17031280 bytes, 159172560 total
> - age 10: 16854792 bytes, 176027352 total
> - age 11: 19192480 bytes, 195219832 total
> - age 12: 20491176 bytes, 215711008 total
> - age 13: 16367528 bytes, 232078536 total
> - age 14: 15536120 bytes, 247614656 total
> 308692.158: [G1Ergonomics (CSet Construction) start choosing CSet,
> _pending_cards: 32768, predicted base time: 38.52 ms, remaining time:
> 61.48 ms, target pause time: 100.00 ms]
> 308692.158: [G1Ergonomics (CSet Construction) add young regions to
> CSet, eden: 91 regions, survivors: 14 regions, predicted young region
> time: 27.76 ms]
> 308692.158: [G1Ergonomics (CSet Construction) finish choosing CSet,
> eden: 91 regions, survivors: 14 regions, old: 0 regions, predicted
> pause time: 66.28 ms, target pause time: 100.00 ms]
> 308692.233: [G1Ergonomics (Concurrent Cycles) request concurrent
> cycle initiation, reason: occupancy higher than threshold, occupancy:
> 52143587328 bytes, allocation request: 0 bytes, threshold: 46172576125
> bytes (65.00 %), source: end of GC]
> , 0.0749020 secs]
> [Parallel Time: 53.9 ms, GC Workers: 18]
> [GC Worker Start (ms): Min: 308692158.6 <tel:308692158.6>, Avg:
> 308692159.0 <tel:308692159.0>, Max: 308692159.4 <tel:308692159.4>,
> Diff: 0.8]
> [Ext Root Scanning (ms): Min: 3.9, Avg: 4.5, Max: 6.4, Diff:
> 2.4, Sum: 81.9]
> [Update RS (ms): Min: 10.2, Avg: 11.6, Max: 12.2, Diff: 2.0,
> Sum: 209.0]
> [Processed Buffers: Min: 15, Avg: 22.5, Max: 31, Diff: 16,
> Sum: 405]
> [Scan RS (ms): Min: 7.8, Avg: 8.0, Max: 8.3, Diff: 0.5, Sum: 144.3]
> [Object Copy (ms): Min: 28.3, Avg: 28.4, Max: 28.5, Diff: 0.2,
> Sum: 510.7]
> [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum:
> 1.2]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1,
> Sum: 0.5]
> [GC Worker Total (ms): Min: 52.3, Avg: 52.6, Max: 53.1, Diff:
> 0.8, Sum: 947.5]
> [GC Worker End (ms): Min: 308692211.6 <tel:308692211.6>, Avg:
> 308692211.7 <tel:308692211.7>, Max: 308692211.7 <tel:308692211.7>,
> Diff: 0.1]
> [Code Root Fixup: 0.0 ms]
> [Clear CT: 9.8 ms]
> [Other: 11.1 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 2.4 ms]
> [Ref Enq: 0.4 ms]
> [Free CSet: 1.1 ms]
> [Eden: 2912.0M(2912.0M)->0.0B(3616.0M) Survivors: 448.0M->416.0M
> Heap: 51.7G(66.2G)->48.9G(66.2G)]
> [Times: user=1.07 sys=0.01, real=0.08 secs]
> 308697.312: [G1Ergonomics (Concurrent Cycles) initiate concurrent
> cycle, reason: concurrent cycle initiation requested]
> 2013-12-30T08:25:31.881-0500: 308697.312: [GC pause (young) (initial-mark)
> Desired survivor size 268435456 bytes, new threshold 15 (max 15)
> - age 1: 17798336 bytes, 17798336 total
> - age 2: 15275456 bytes, 33073792 total
> - age 3: 27940176 bytes, 61013968 total
> - age 4: 15716648 bytes, 76730616 total
> - age 5: 16474656 bytes, 93205272 total
> - age 6: 14249232 bytes, 107454504 total
> - age 7: 15187536 bytes, 122642040 total
> - age 8: 15073808 bytes, 137715848 total
> - age 9: 17362752 bytes, 155078600 total
> - age 10: 17031280 bytes, 172109880 total
> - age 11: 16854792 bytes, 188964672 total
> - age 12: 19124800 bytes, 208089472 total
> - age 13: 20491176 bytes, 228580648 total
> - age 14: 16367528 bytes, 244948176 total
> 308697.313: [G1Ergonomics (CSet Construction) start choosing CSet,
> _pending_cards: 31028, predicted base time: 37.87 ms, remaining time:
> 62.13 ms, target pause time: 100.00 ms]
> 308697.313: [G1Ergonomics (CSet Construction) add young regions to
> CSet, eden: 113 regions, survivors: 13 regions, predicted young region
> time: 27.99 ms]
> 308697.313: [G1Ergonomics (CSet Construction) finish choosing CSet,
> eden: 113 regions, survivors: 13 regions, old: 0 regions, predicted
> pause time: 65.86 ms, target pause time: 100.00 ms]
> , 0.0724890 secs]
> [Parallel Time: 51.9 ms, GC Workers: 18]
> [GC Worker Start (ms): Min: 308697313.3 <tel:308697313.3>, Avg:
> 308697313.7 <tel:308697313.7>, Max: 308697314.0 <tel:308697314.0>,
> Diff: 0.6]
> [Ext Root Scanning (ms): Min: 4.3, Avg: 5.7, Max: 16.7, Diff:
> 12.3, Sum: 101.8]
> [Update RS (ms): Min: 0.0, Avg: 9.3, Max: 10.4, Diff: 10.4, Sum:
> 166.9]
> [Processed Buffers: Min: 0, Avg: 22.0, Max: 30, Diff: 30,
> Sum: 396]
> [Scan RS (ms): Min: 6.4, Avg: 8.5, Max: 13.0, Diff: 6.5, Sum: 152.3]
> [Object Copy (ms): Min: 22.5, Avg: 27.1, Max: 27.7, Diff: 5.2,
> Sum: 487.0]
> [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum:
> 1.0]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1,
> Sum: 0.6]
> [GC Worker Total (ms): Min: 50.2, Avg: 50.5, Max: 50.9, Diff:
> 0.6, Sum: 909.5]
> [GC Worker End (ms): Min: 308697364.2 <tel:308697364.2>, Avg:
> 308697364.2 <tel:308697364.2>, Max: 308697364.3 <tel:308697364.3>,
> Diff: 0.1]
> [Code Root Fixup: 0.0 ms]
> [Clear CT: 9.9 ms]
> [Other: 10.8 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 2.8 ms]
> [Ref Enq: 0.4 ms]
> [Free CSet: 0.9 ms]
> [Eden: 3616.0M(3616.0M)->0.0B(3520.0M) Survivors: 416.0M->448.0M
> Heap: 52.5G(66.2G)->49.0G(66.2G)]
> [Times: user=1.01 sys=0.00, real=0.07 secs]
> 2013-12-30T08:25:31.954-0500: 308697.385: [GC
> concurrent-root-region-scan-start]
> 2013-12-30T08:25:31.967-0500: 308697.398: [GC
> concurrent-root-region-scan-end, 0.0131710 secs]
> 2013-12-30T08:25:31.967-0500: 308697.398: [GC concurrent-mark-start]
> 2013-12-30T08:25:36.566-0500: 308701.997: [GC concurrent-mark-end,
> 4.5984140 secs]
> 2013-12-30T08:25:36.570-0500: 308702.002: [GC remark
> 2013-12-30T08:25:36.573-0500: 308702.004: [GC ref-proc, 0.0126990
> secs], 0.0659540 secs]
> [Times: user=0.87 sys=0.00, real=0.06 secs]
> 2013-12-30T08:25:36.641-0500: 308702.072: [GC cleanup 52G->52G(66G),
> 0.5487830 secs]
> [Times: user=9.66 sys=0.06, real=0.54 secs]
> 2013-12-30T08:25:37.190-0500: 308702.622: [GC concurrent-cleanup-start]
> 2013-12-30T08:25:37.190-0500: 308702.622: [GC concurrent-cleanup-end,
> 0.0000480 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/20140102/ab765b84/attachment.html
More information about the hotspot-gc-use
mailing list