GC Logs - Need help discerning what's up
Need some help with this one. Why would a concurrent mark last for over 4000 seconds?
43415.531: [GC 43415.531: [ParNew: 130944K->0K(131008K), 0.0068140 secs] 216204K->86072K(1535936K) icms_dc=0 , 0.0070140 secs]
43446.687: [GC 43446.687: [ParNew: 130944K->0K(131008K), 0.0067580 secs] 217016K->86928K(1535936K) icms_dc=0 , 0.0069550 secs]
43478.323: [GC 43478.323: [ParNew: 130944K->0K(131008K), 0.0044850 secs] 217872K->87387K(1535936K) icms_dc=0 , 0.0046870 secs]
43520.735: [GC 43520.735: [ParNew: 130944K->0K(131008K), 0.0047830 secs] 218331K->87873K(1535936K) icms_dc=0 , 0.0049710 secs]
43557.266: [GC 43557.267: [ParNew: 130944K->0K(131008K), 0.0047220 secs] 218817K->88376K(1535936K) icms_dc=0 , 0.0049190 secs]
43617.278: [Full GC 43617.278: [CMS43617.573: [CMS-concurrent-mark: 0.296/4392.783 secs]
(concurrent mode failure): 88376K->40783K(1404928K), 0.7593660 secs] 218441K->40783K(1535936K), [CMS Perm : 31443K->31438K(52460K)] icms_dc=0 , 0.7596350 secs]
Here are the current settings.
-Xms1500m -Xmx1500m
-XX:NewSize=128M -XX:MaxPermSize=512M
-XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode -XX:+CMSIncrementalPacing -XX:CMSIncrementalDutyCycleMin=0 -XX:CMSIncrementalDutyCycle=10 -XX:-DisableExplicitGC
Any recommendations on changes?
Lukas
# 1
Hi,
in your output, there is a full collection which is a stop-the-world collection and collects all genenerations of your heap. So it's not just a concurrent mark. This could be caused by a concurrent mode failure or a System.gc() call in your application (which also leads to the output "concurrent mode failure").
Have a look at these two blog entries to see what all this means and how you could try to avoid it:
http://blogs.sun.com/jonthecollector/entry/what_the_heck_s_a
http://blogs.sun.com/jonthecollector/entry/why_now
One thing: Are you aware that with the parameter -XX:-DisableExplicitGC
you do allow explicit GCs? Since this is the default, there is no use in setting this parameter. If you want to disable them (which would be worth a try), you have to specify -XX:+DisableExplicitGC.
Now, even if a full collection happens, why does it take to long? One reason I could think of is that you do not have enough physical memory and some parts of your old heap has been paged out to disk. At the collection, it then needs to be paged in which could take a while.
Nick.
# 4
Glad to hear that you found the problem but to get to the early question
about why the concurrent mark was taking so long, you are using
incremental CMS and the amount of work that is being done between
each minor collection is very small. The icms_dc=0 in the log
indicates that only a little bit of work is being done (not really 0 but
rounds to 0).The automatic pacing for incremental CMS (which
calculates how much work to do in each increment) is not working
well. Consider adding -XX:CMSIncrementalDutyCycleMin=10 to
set a minimum amount of work for each cycle. The "10" is just
a starting point. Legal values are between 1-100. Experiment with it.
