Eagle~<div><br></div><div>If I had to guess, I would attribute the increase in young collection times to fragmentation in the old gen making promotion more expensive. Given your tenuring distribution, I would just set MTT to 2.</div>
<div><br></div><div>Matt<br><br><div class="gmail_quote">On Thu, Jul 22, 2010 at 2:36 PM, Eagle Kessler <span dir="ltr"><<a href="mailto:eagle.kessler@gmail.com">eagle.kessler@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex;">
We've switched to the throughput collector with a max pause time goal, and that seems to be behaving well. I'm still curious about the behavior that I'm seeing with CMS, though.<br><br>I ran some tests with -XX:+PrintTenuringDistribution and without setting MaxTenuringThreshold, and I'm still seeing the behavior. Both of these tests were executed under constant load:<br>
<br>512mb heap (128mb young gen), MTT=0:<br>62.537: [GC 62.537: [ParNew<br>Desired survivor size 491520 bytes, new threshold 0 (max 0)<br>: 129152K->0K(130112K), 0.0064317 secs] 143985K->16058K(523328K), 0.0065156 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] <br>
95.633: [GC 95.633: [ParNew<br>Desired survivor size 491520 bytes, new threshold 0 (max 0)<br>: 129152K->0K(130112K), 0.0030186 secs] 145210K->16614K(523328K), 0.0030929 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] <br>
127.882: [GC 127.882: [ParNew<br>Desired survivor size 491520 bytes, new threshold 0 (max 0)<br>: 129152K->0K(130112K), 0.0042069 secs] 145766K->17285K(523328K), 0.0042783 secs] [Times: user=0.01 sys=0.02, real=0.00 secs] <br>
158.086: [GC 158.086: [ParNew<br>Desired survivor size 491520 bytes, new threshold 0 (max 0)<br>: 129152K->0K(130112K), 0.0045986 secs] 146437K->17955K(523328K), 0.0046896 secs] [Times: user=0.02 sys=0.02, real=0.01 secs] <br>
<br>Rising to <br>5021.415: [GC 5021.415: [ParNew<br>Desired survivor size 491520 bytes, new threshold 0 (max 0)<br>: 129152K->0K(130112K), 0.0604269 secs] 225694K->97083K(523328K), 0.0605133 secs] [Times: user=0.10 sys=0.61, real=0.06 secs] <br>
5053.611: [GC 5053.611: [ParNew<br>Desired survivor size 491520 bytes, new threshold 0 (max 0)<br>: 129152K->0K(130112K), 0.0569357 secs] 226235K->97636K(523328K), 0.0570316 secs] [Times: user=0.10 sys=0.60, real=0.05 secs] <br>
5084.401: [GC 5084.401: [ParNew<br>Desired survivor size 491520 bytes, new threshold 0 (max 0)<br>: 129152K->0K(130112K), 0.0591064 secs] 226788K->98088K(523328K), 0.0591840 secs] [Times: user=0.09 sys=0.62, real=0.06 secs] <br>
<br><br>Similarly, 512mb heap, 128mb young gen, and no MTT:<br>83.708: [GC 83.708: [ParNew<br>Desired survivor size 3702784 bytes, new threshold 15 (max 15)<br>- age 1: 626008 bytes, 626008 total<br>- age 2: 736336 bytes, 1362344 total<br>
: 120669K->1759K(123840K), 0.0034469 secs] 135502K->16593K(517056K), 0.0035234 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] <br>109.627: [GC 109.627: [ParNew<br>Desired survivor size 3702784 bytes, new threshold 15 (max 15)<br>
- age 1: 634688 bytes, 634688 total<br>- age 2: 268624 bytes, 903312 total<br>- age 3: 736016 bytes, 1639328 total<br>: 118367K->2275K(123840K), 0.0036776 secs] 133201K->17109K(517056K), 0.0037455 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] <br>
137.495: [GC 137.495: [ParNew<br>Desired survivor size 3702784 bytes, new threshold 15 (max 15)<br>- age 1: 479728 bytes, 479728 total<br>- age 2: 269064 bytes, 748792 total<br>- age 3: 267904 bytes, 1016696 total<br>
- age 4: 735952 bytes, 1752648 total<br>: 118883K->2396K(123840K), 0.0040557 secs] 133717K->17230K(517056K), 0.0041302 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] <br>165.090: [GC 165.090: [ParNew<br>
Desired survivor size 3702784 bytes, new threshold 15 (max 15)<br>- age 1: 403856 bytes, 403856 total<br>- age 2: 267736 bytes, 671592 total<br>- age 3: 268616 bytes, 940208 total<br>- age 4: 267904 bytes, 1208112 total<br>
- age 5: 729072 bytes, 1937184 total<br>: 119004K->2668K(123840K), 0.0046744 secs] 133838K->17501K(517056K), 0.0047473 secs] [Times: user=0.04 sys=0.02, real=0.00 secs] <br><br>Rising to<br>4981.917: [GC 4981.918: [ParNew<br>
Desired survivor size 3702784 bytes, new threshold 14 (max 15)<br>- age 1: 533872 bytes, 533872 total<br>- age 2: 269336 bytes, 803208 total<br>- age 3: 268048 bytes, 1071256 total<br>- age 4: 268272 bytes, 1339528 total<br>
- age 5: 265880 bytes, 1605408 total<br>- age 6: 241704 bytes, 1847112 total<br>- age 7: 241112 bytes, 2088224 total<br>- age 8: 239680 bytes, 2327904 total<br>- age 9: 233632 bytes, 2561536 total<br>
- age 10: 231040 bytes, 2792576 total<br>- age 11: 231040 bytes, 3023616 total<br>- age 12: 232256 bytes, 3255872 total<br>- age 13: 232256 bytes, 3488128 total<br>- age 14: 231040 bytes, 3719168 total<br>
: 122652K->4440K(123840K), 0.0654827 secs] 173869K->56113K(517056K), 0.0655671 secs] [Times: user=0.17 sys=0.62, real=0.07 secs] <br>5009.679: [GC 5009.679: [ParNew<br>Desired survivor size 3702784 bytes, new threshold 14 (max 15)<br>
- age 1: 673136 bytes, 673136 total<br>- age 2: 271704 bytes, 944840 total<br>- age 3: 269232 bytes, 1214072 total<br>- age 4: 268088 bytes, 1482160 total<br>- age 5: 264528 bytes, 1746688 total<br>
- age 6: 244280 bytes, 1990968 total<br>- age 7: 238320 bytes, 2229288 total<br>- age 8: 241112 bytes, 2470400 total<br>- age 9: 233416 bytes, 2703816 total<br>- age 10: 231040 bytes, 2934856 total<br>
- age 11: 231040 bytes, 3165896 total<br>- age 12: 231040 bytes, 3396936 total<br>- age 13: 232256 bytes, 3629192 total<br>- age 14: 232256 bytes, 3861448 total<br>: 121048K->5058K(123840K), 0.0675964 secs] 172721K->56957K(517056K), 0.0677232 secs] [Times: user=0.17 sys=0.66, real=0.06 secs] <br>
5037.742: [GC 5037.742: [ParNew<br>Desired survivor size 3702784 bytes, new threshold 14 (max 15)<br>- age 1: 582296 bytes, 582296 total<br>- age 2: 268128 bytes, 850424 total<br>- age 3: 271528 bytes, 1121952 total<br>
- age 4: 269192 bytes, 1391144 total<br>- age 5: 264952 bytes, 1656096 total<br>- age 6: 242496 bytes, 1898592 total<br>- age 7: 240752 bytes, 2139344 total<br>- age 8: 238320 bytes, 2377664 total<br>
- age 9: 234776 bytes, 2612440 total<br>- age 10: 231040 bytes, 2843480 total<br>- age 11: 231040 bytes, 3074520 total<br>- age 12: 231040 bytes, 3305560 total<br>- age 13: 231040 bytes, 3536600 total<br>
- age 14: 232256 bytes, 3768856 total<br>: 121666K->5991K(123840K), 0.0649960 secs] 173565K->58116K(517056K), 0.0650795 secs] [Times: user=0.17 sys=0.64, real=0.06 secs] <br><br><br>I'll look into why 232k lives through seven minutes of collections, but in both cases a full collection (triggered through JMX) brought the heap down to ~12mb and removed the "accumulated" ParNew time. Any idea why I'm seeing the slow increase in ParNew collection times and/or more tests that I should be running to diagnose it? I can provide the full logs if you'd like, I've abbreviated them here to avoid sending long messages to the entire list.<div>
<div></div><div class="h5"><br>
<br><br><div class="gmail_quote">On Wed, Jul 21, 2010 at 2:16 PM, Y. S. Ramakrishna <span dir="ltr"><<a href="mailto:y.s.ramakrishna@oracle.com" target="_blank">y.s.ramakrishna@oracle.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0pt 0pt 0pt 0.8ex;border-left:1px solid rgb(204, 204, 204);padding-left:1ex">
<div><br>
<br>
On 07/21/10 13:41, Eagle Kessler wrote:<br>
<blockquote class="gmail_quote" style="margin:0pt 0pt 0pt 0.8ex;border-left:1px solid rgb(204, 204, 204);padding-left:1ex">
Checking the configs, it looks like we are explicitly setting MTT to 0:<br>
<br>
# Min, max, total JVM size (-Xms -Xmx)<br>
JVM_SIZE="-server -Xms2g -Xmx2g"<br>
<br>
# New Generation Sizes (-XX:NewSize -XX:MaxNewSize)<br>
<br>
JVM_SIZE_NEW="-XX:NewSize=512m -XX:MaxNewSize=512m"<br>
<br>
# Perm Generation Sizes (-XX:PermSize -XX:MaxPermSize)<br>
JVM_SIZE_PERM="-XX:PermSize=128m -XX:MaxPermSize=128m"<br>
<br>
# Type of Garbage Collector to use<br>
<br>
JVM_GC_TYPE="-XX:+UseConcMarkSweepGC -XX:+UseParNewGC"<br>
<br>
JVM_GC_OPTS="-XX:MaxTenuringThreshold=0 -XX:SurvivorRatio=128"<br>
<br>
I agree that in this case we definitely want to be using survivor spaces (I'm unfortunately not in charge of the default GC settings yet). However, I didn't know that running without survivor spaces could cause this kind of behavior. Why does running without survivor spaces cause such a large performance issue?<br>
</blockquote>
<br></div>
See below.<div><br>
<br>
<blockquote class="gmail_quote" style="margin:0pt 0pt 0pt 0.8ex;border-left:1px solid rgb(204, 204, 204);padding-left:1ex">
<br>
Regardless, I'll ask that -XX:+PrintTenuringDistribution be added to the configs, along with a non-zero MTT, and see if the issue persists. The <br>
</blockquote>
<br></div>
And of course SurvivorRatio a more reasonable value like 6 or 8,<br>
depending on expected survival rate etc.<div><br>
<br>
<blockquote class="gmail_quote" style="margin:0pt 0pt 0pt 0.8ex;border-left:1px solid rgb(204, 204, 204);padding-left:1ex">
rising ParNew times seem like they would be unrelated to the tenuring threshold, though, wouldn't they?<br>
</blockquote>
<br></div>
No, it's related in the sense that MTT=0 was resulting in very very short-lived<br>
data to promote into the old gen. This can cause object dempgraphics (size and<br>
age dirstribution) to be very non-stationary, and confuse the heuristics<br>
for sizing the free list inventory. It of course also places large pressure<br>
on the old gen allocator, increases fragmentation, increases mutation rates<br>
and so on.<br>
<br>
The only thing it might not affect much is the initial mark pauses,<br>
which will probably stay as they were before.<br>
<br>
-- ramki<br>
<br>
<blockquote class="gmail_quote" style="margin:0pt 0pt 0pt 0.8ex;border-left:1px solid rgb(204, 204, 204);padding-left:1ex"><div><div></div><div>
<br>
On Wed, Jul 21, 2010 at 12:40 PM, Y. S. Ramakrishna <<a href="mailto:y.s.ramakrishna@oracle.com" target="_blank">y.s.ramakrishna@oracle.com</a> <mailto:<a href="mailto:y.s.ramakrishna@oracle.com" target="_blank">y.s.ramakrishna@oracle.com</a>>> wrote:<br>
<br>
oh, and the "(max 0)" seems to imply you have somehow ended up<br>
asking for<br>
MaxTenuringThreshold=0 which can be disastrous. It is possible that the<br>
default settings for CMS on certain very old JVM's did indeed result in<br>
MTT=0 (but memory is fading of that era), so if using such older vintage<br>
of JVM's, explicitly setting MTT and SurvivorRatio higher is a good<br>
idea.<br>
<br>
-- ramki<br>
<br>
<br>
On 07/21/10 12:34, Y. S. Ramakrishna wrote:<br>
<br>
Yes, like what i think Matt is getting at, i'd configure<br>
sufficiently<br>
large survivor spaces. Even if you expect most of your objects<br>
to die young,<br>
you'd want survivor spaces large enough to keep at least age 1<br>
objects in<br>
the survivor space. If as you state no medium- to ling-lived<br>
state is<br>
retained, your data is mostly short-lived and you'll be able to<br>
do without<br>
any promotion at all. Your problem here is that somehow your<br>
survivor<br>
spaces may have disappeared. (+PrintHeapAtGC will tell you, and<br>
of course examining yr JVM options should shed more light on<br>
that apparent<br>
disappearance.)<br>
<br>
-- ramki<br>
<br>
On 07/21/10 10:09, Eagle Kessler wrote:<br>
<br>
Hello all,<br>
I've got a web service that I'm seeing some very strange<br>
behavior on around it's garbage collection, and was<br>
wondering if someone here could explain why it might be<br>
happening. The service itself is fairly simple: Take in data<br>
from a few sources and merge them with the existing data in<br>
the database. It stores nearly no state while doing this,<br>
and indeed heap dumps taken 1, 24, and 72 hours after boot<br>
indicate that we have a consistent ~12mb of live data (in a<br>
2GB heap, but I hope that's not what is causing this).<br>
<br>
The GC logs, though, don't look very happy at all. After our<br>
start up period, they settle into a fairly consistent pattern:<br>
<br>
1041.159: [GC 1041.159: [ParNew<br>
Desired survivor size 2064384 bytes, new threshold 0 (max 0)<br>
<br>
: 516224K->0K(520256K), 0.0170322 secs]<br>
537266K->22659K(2093120K), 0.0171330 secs] [Times: user=0.04<br>
sys=0.01, real=0.02 secs] 1606.500: [GC 1606.500: [ParNew<br>
Desired survivor size 2064384 bytes, new threshold 0 (max 0)<br>
<br>
: 516224K->0K(520256K), 0.0173235 secs]<br>
538883K->24214K(2093120K), 0.0174138 secs] [Times: user=0.04<br>
sys=0.03, real=0.02 secs] 2040.773: [GC 2040.773: [ParNew<br>
Desired survivor size 2064384 bytes, new threshold 0 (max 0)<br>
<br>
: 516224K->0K(520256K), 0.0196319 secs]<br>
540438K->25737K(2093120K), 0.0197275 secs] [Times: user=0.05<br>
sys=0.02, real=0.02 secs]<br>
Which we would be very nice if it kept going like that.<br>
However, by the first time the CMS collector runs, things<br>
aren't working nearly as well:<br>
<br>
214182.439: [GC 214182.439: [ParNew<br>
Desired survivor size 2064384 bytes, new threshold 0 (max 0)<br>
: 516224K->0K(520256K), 1.0146996 secs]<br>
1297278K->782575K(2093120K), 1.0148799 secs] [Times:<br>
user=1.21 sys=0.58, real=1.01 secs]<br>
214247.437: [GC 214247.438: [ParNew<br>
Desired survivor size 2064384 bytes, new threshold 0 (max 0)<br>
: 516224K->0K(520256K), 1.2310274 secs]<br>
1298799K->784188K(2093120K), 1.2311534 secs] [Times:<br>
user=1.46 sys=0.69, real=1.23 secs]<br>
214313.642: [GC 214313.642: [ParNew<br>
Desired survivor size 2064384 bytes, new threshold 0 (max 0)<br>
: 516224K->0K(520256K), 1.2183258 secs]<br>
1300412K->785710K(2093120K), 1.2184848 secs] [Times:<br>
user=1.45 sys=0.65, real=1.22 secs]<br>
<br>
The increasing sys time is a bit worrying, but it seems like<br>
the actual GC time is rising as well, even though we aren't<br>
collecting any more young-gen garbage. At this point, CMS<br>
went off<br>
<br>
214380.695: [GC [1 CMS-initial-mark: 787188K(1572864K)]<br>
787195K(2093120K), 1.8929842 secs] [Times: user=1.50<br>
sys=0.02, real=1.89 secs]<br>
214382.589: [CMS-concurrent-mark-start]<br>
214383.056: [CMS-concurrent-mark: 0.467/0.467 secs] [Times:<br>
user=1.81 sys=0.01, real=0.47 secs] 214383.056:<br>
[CMS-concurrent-preclean-start]<br>
214383.064: [CMS-concurrent-preclean: 0.008/0.008 secs]<br>
[Times: user=0.01 sys=0.00, real=0.01 secs]<br>
214383.064: [CMS-concurrent-abortable-preclean-start]<br>
CMS: abort preclean due to time 214388.133:<br>
[CMS-concurrent-abortable-preclean: 0.242/5.069 secs]<br>
[Times: user=5.02 sys=0.02, real=5.07 secs] 214388.159:<br>
[GC[YG occupancy: 51943 K (520256 K)]214388.159: [Rescan<br>
(parallel) , 1.5403455 secs]214389.699: [weak refs<br>
processing, 0.0050170 secs] [1 CMS-remark:<br>
787188K(1572864K)] 839132K(2093120K), 1.5458536 secs]<br>
[Times: user=1.80 sys=0.71, real=1.55 secs]<br>
214389.705: [CMS-concurrent-sweep-start]<br>
214390.439: [CMS-concurrent-sweep: 0.671/0.734 secs] [Times:<br>
user=1.35 sys=0.00, real=0.73 secs] 214390.439:<br>
[CMS-concurrent-reset-start]<br>
214390.621: [CMS-concurrent-reset: 0.183/0.183 secs] [Times:<br>
user=0.20 sys=0.02, real=0.18 secs]<br>
<br>
It seems like a) initial-mark shouldn't take 1.8 seconds, b)<br>
if we really do only have 12mb of live data, CMS should have<br>
collected a lot more than it did (the next ParNew collection<br>
reported ~545MB of old gen in use), and c) 50% heap usage<br>
with very little promotion seems very early for the<br>
collector to go off.<br>
<br>
The next CMS cycle is at 434,973 seconds, by which point the<br>
young gen collections are taking 3 seconds (user 3.59, sys<br>
1.60, real 3.09). The initial mark takes 4.82 seconds (user<br>
3.82, sys 0.02, real 4.82), and sweeps down to 1.1gb of used<br>
old gen. I haven't yet confirmed it, but given the previous<br>
heap dumps I'd guess that they will claim 12mb of live<br>
objects and 1.1gb of dead objects. The current young gen<br>
collections (at 497,601 seconds) are taking ~3.7 seconds<br>
(4.33 user, 2.03 sys) Any idea what could be going on here?<br>
We're running JDK 1.6_16.<br>
<br>
-- Eagle Kessler<br>
<br>
<br>
------------------------------------------------------------------------<br>
<br>
_______________________________________________<br>
hotspot-gc-use mailing list<br>
<a href="mailto:hotspot-gc-use@openjdk.java.net" target="_blank">hotspot-gc-use@openjdk.java.net</a><br></div></div>
<mailto:<a href="mailto:hotspot-gc-use@openjdk.java.net" target="_blank">hotspot-gc-use@openjdk.java.net</a>><div><br>
<a href="http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use" target="_blank">http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use</a><br>
<br>
_______________________________________________<br>
hotspot-gc-use mailing list<br>
<a href="mailto:hotspot-gc-use@openjdk.java.net" target="_blank">hotspot-gc-use@openjdk.java.net</a><br></div>
<mailto:<a href="mailto:hotspot-gc-use@openjdk.java.net" target="_blank">hotspot-gc-use@openjdk.java.net</a>><div><br>
<a href="http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use" target="_blank">http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use</a><br>
<br>
<br>
<br>
<br>
-- <br>
Eagle Kessler<br>
</div></blockquote>
</blockquote></div><br><br clear="all"><br></div></div>-- <br><font color="#888888">Eagle Kessler<br>
</font><br>_______________________________________________<br>
hotspot-gc-use mailing list<br>
<a href="mailto:hotspot-gc-use@openjdk.java.net">hotspot-gc-use@openjdk.java.net</a><br>
<a href="http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use" target="_blank">http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use</a><br>
<br></blockquote></div><br></div>