Promotion failures: indication of CMS fragmentation?
Chi Ho Kwok
chkwok at digibites.nl
Tue Mar 20 10:44:21 PDT 2012
Hi Teras,
If the new setting works, is there still a reason to tune it further?
Further, from the stats, I see that that contrary to what you say, most of
the objects *are* getting collected in the young gen and survivor space.
Sure, there are some states that have to be kept for hours, but that's what
the old gen is for. For eden + survivor, I can see that the ~68M survivor
space in the new vm setup is enough to let only a tiny fraction into the
old gen: from the 590MB collected, only ~1MB made it into the old gen, and
on the next collection, only the ~2MB "age 15" group will get promoted if
they survive, unless a huge spike drive multiple generations away and
threshold drops below 15.
It's a lot easier to promote only 1-2MB of data x times per minute than 2M
* 2x times per minute - with 2 times as much young gen, the collector runs
half as often. You can decrease the survivor ratio a bit more for safety
margin (to 3-4?, is it set to 5 now? calc says ~10%), but not to 1, you
won't have enough space left young gen then.
Oh, and if you want to take a look at the live situation, try jstat on a
shell. It's the best tool you have to visualize GC, unless you manage to
convince ops to let you connect a jvisualvm+visualgc to live servers.
Chi Ho
On Tue, Mar 20, 2012 at 5:36 PM, Taras Tielkes <taras.tielkes at gmail.com>wrote:
> Hi,
>
> I've collected -XX:+PrintTenuringDistribution data from a node in our
> production environment, running -Xmx5g -Xmn400m -XX:SurvivorRatio=8.
> On one other production node, we've configured a larger new gen, and
> larger survivor spaces (-Xmx5g -Xmn800m -XX:SurvivorRatio=4).
> This node has -XX:+PrintTenuringDistribution logging as well.
>
> The node running the larger new gen and survivor spaces has not run
> into a promotion failure yet, while the ones still running the old
> config have hit a few.
> The promotion failures are typically experienced at high load periods,
> which makes sense, as allocation and promotion will experience a spike
> in those periods as well.
>
> The inherent nature of the application implies relatively long
> sessions (towards a few hours), retaining a fair amout of state up to
> an hour.
> I believe this is the main reason of the relatively high promotion
> rate we're experiencing.
>
>
> Here's a fragment of gc log from one of the nodes running the older
> (smaller) new gen, including a promotion failure:
> -------------------------
> 2012-03-15T18:32:17.785+0100: 796604.225: [GC 796604.225: [ParNew
> Desired survivor size 20971520 bytes, new threshold 8 (max 15)
> - age 1: 2927728 bytes, 2927728 total
> - age 2: 2428512 bytes, 5356240 total
> - age 3: 2696376 bytes, 8052616 total
> - age 4: 2623576 bytes, 10676192 total
> - age 5: 3365576 bytes, 14041768 total
> - age 6: 2792272 bytes, 16834040 total
> - age 7: 2233008 bytes, 19067048 total
> - age 8: 2263824 bytes, 21330872 total
> : 358709K->29362K(368640K), 0.0461460 secs]
> 3479492K->3151874K(5201920K), 0.0467320 secs] [Times: user=0.34
> sys=0.01, real=0.05 secs]
> 2012-03-15T18:32:21.546+0100: 796607.986: [GC 796607.986: [ParNew (0:
> promotion failure size = 25) (1: promotion failure size = 25) (2:
> promotion failure size = 25) (3: promotion failure size = 25) (4:
> promotion failure size = 25) (5
> : promotion failure size = 25) (6: promotion failure size = 341) (7:
> promotion failure size = 25) (promotion failed)
> Desired survivor size 20971520 bytes, new threshold 8 (max 15)
> - age 1: 3708208 bytes, 3708208 total
> - age 2: 2174384 bytes, 5882592 total
> - age 3: 2383256 bytes, 8265848 total
> - age 4: 2689912 bytes, 10955760 total
> - age 5: 2621832 bytes, 13577592 total
> - age 6: 3360440 bytes, 16938032 total
> - age 7: 2784136 bytes, 19722168 total
> - age 8: 2220232 bytes, 21942400 total
> : 357042K->356456K(368640K), 0.2734100 secs]796608.259: [CMS:
> 3124189K->516640K(4833280K), 6.8127070 secs]
> 3479554K->516640K(5201920K), [CMS Perm : 142423K->142284K(262144K)],
> 7.0867850 secs] [Times: user=7.32 sys=0.07, real=7.09 secs]
> 2012-03-15T18:32:30.279+0100: 796616.719: [GC 796616.720: [ParNew
> Desired survivor size 20971520 bytes, new threshold 1 (max 15)
> - age 1: 29721456 bytes, 29721456 total
> : 327680K->40960K(368640K), 0.0403130 secs]
> 844320K->557862K(5201920K), 0.0409070 secs] [Times: user=0.27
> sys=0.01, real=0.04 secs]
> 2012-03-15T18:32:32.701+0100: 796619.141: [GC 796619.141: [ParNew
> Desired survivor size 20971520 bytes, new threshold 15 (max 15)
> - age 1: 10310176 bytes, 10310176 total
> -------------------------
>
> For contrast, here's a gc log fragment from the single node running
> the larger new gen and larger survivor spaces:
> (the fragment is from the same point in time, with the nodes
> experiencing equal load)
> -------------------------
> 2012-03-15T18:32:12.067+0100: 797119.336: [GC 797119.336: [ParNew
> Desired survivor size 69894144 bytes, new threshold 15 (max 15)
> - age 1: 5611536 bytes, 5611536 total
> - age 2: 3731888 bytes, 9343424 total
> - age 3: 3450672 bytes, 12794096 total
> - age 4: 3314744 bytes, 16108840 total
> - age 5: 3459888 bytes, 19568728 total
> - age 6: 3334712 bytes, 22903440 total
> - age 7: 3671960 bytes, 26575400 total
> - age 8: 3841608 bytes, 30417008 total
> - age 9: 2035392 bytes, 32452400 total
> - age 10: 1975056 bytes, 34427456 total
> - age 11: 2021344 bytes, 36448800 total
> - age 12: 1520752 bytes, 37969552 total
> - age 13: 1494176 bytes, 39463728 total
> - age 14: 2355136 bytes, 41818864 total
> - age 15: 1279000 bytes, 43097864 total
> : 603473K->61640K(682688K), 0.0756570 secs]
> 3373284K->2832383K(5106368K), 0.0762090 secs] [Times: user=0.56
> sys=0.00, real=0.08 secs]
> 2012-03-15T18:32:18.200+0100: 797125.468: [GC 797125.469: [ParNew
> Desired survivor size 69894144 bytes, new threshold 15 (max 15)
> - age 1: 6101320 bytes, 6101320 total
> - age 2: 4446776 bytes, 10548096 total
> - age 3: 3701384 bytes, 14249480 total
> - age 4: 3438488 bytes, 17687968 total
> - age 5: 3295360 bytes, 20983328 total
> - age 6: 3403320 bytes, 24386648 total
> - age 7: 3323368 bytes, 27710016 total
> - age 8: 3665760 bytes, 31375776 total
> - age 9: 2427904 bytes, 33803680 total
> - age 10: 1418656 bytes, 35222336 total
> - age 11: 1955192 bytes, 37177528 total
> - age 12: 2006064 bytes, 39183592 total
> - age 13: 1520768 bytes, 40704360 total
> - age 14: 1493728 bytes, 42198088 total
> - age 15: 2354376 bytes, 44552464 total
> : 607816K->62650K(682688K), 0.0779270 secs]
> 3378559K->2834643K(5106368K), 0.0784690 secs] [Times: user=0.58
> sys=0.00, real=0.08 secs]
> -------------------------
>
> Questions:
>
> 1) From the tenuring distributions, it seems that the application
> benefits from larger new gen and survivor spaces.
> The next thing we'll try is to run with -Xmn1g -XX:SurvivorRatio=2,
> and see if the ParNew times are still acceptable.
> Does this seem a sensible approach in this context?
> Are there other variables beyond ParNew times that limit scaling the
> new gen to a large size?
>
> 2) Given the object age demographics inherent to our application, we
> can not expect to see the majority of data get collected in the new
> gen.
>
> Our approach to fight the promotion failures consists of three aspects:
> a) Lower the overall allocation rate of our application (by improving
> wasteful hotspots), to decrease overall ParNew collection frequency.
> b) Configure the new gen and survivor spaces as large as possible,
> keeping an eye on ParNew times and overall new/tenured ratio.
> c) Try to refactor the data structures that form the bulk of promoted
> data, to retain only the strictly required subgraphs.
>
> Is there anything else I can try or measure, in order to better
> understand the problem?
>
> Thanks in advance,
> Taras
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20120320/e98ea510/attachment-0001.html
More information about the hotspot-gc-use
mailing list