简述:CMS垃圾收集器似乎未能收集越来越多的垃圾;最终,我们的JVM填满了,并且应用程序变得无响应。通过外部工具(JConsole或jmap -histo:live
)强制进行GC一次可以清理它。
更新:该问题似乎与JConsole的JTop插件有关;如果我们不运行JConsole或以没有JTop插件的方式运行它,则该问题消失。
(技术说明:我们在Linux 2.6.9盒子上运行Sun JDK 1.6.0_07,32位。除非有不可避免的重大原因,否则升级JDK版本并不是一个真正的选择。此外,我们的系统未连接到可访问互联网的计算机,因此无法提供JConsole等的截图。)
我们目前正在使用以下标志运行JVM:
-server -Xms3072m -Xmx3072m -XX:NewSize=512m -XX:MaxNewSize=512m
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+CMSParallelRemarkEnabled
-XX:CMSInitiatingOccupancyFraction=70
-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
-XX:+DisableExplicitGC
在JConsole中观察内存图形,我们的应用程序在前几个小时内会每15分钟左右运行一次full GC;在每次full GC之后,仍有越来越多的内存被使用。几个小时后,系统达到稳定状态,CMS old gen中大约使用了2GB的内存。
这听起来像是一个经典的内存泄漏,但如果我们使用任何强制进行full GC的工具(在JConsole中点击“收集垃圾”按钮或运行jmap -histo:live
等),旧代突然降至使用约500MB,并且我们的应用程序在接下来的几个小时内重新变得响应(在此期间相同的模式继续- 每次full GC之后,越来越多的old gen已满。)
值得注意的一件事是,在JConsole中,报告的ConcurrentMarkSweep GC计数将保持为0,直到我们使用jconsole/jmap等强制进行GC。
通过连续使用jmap -histo
和jmap -histo:live
,我能够确定明显未被收集的对象包括:
- 几百万个
HashMap
和HashMap$Entry
数组(1:1比例) - 几百万个
Vector
和Object数组(1:1比例,与HashMap数量大约相同) - 几百万个
HashSet
、Hashtable
和com.sun.jmx.remote.util.OrderClassLoader
,以及Hashtable$Entry
数组(每种类型数量大约相同;大约是HashMap和Vector的一半)
以下是GC输出的一些摘录;我对它们的解释似乎是CMS GC被中止而没有转移到停机GC。我是否会误解这个输出?有什么会导致这种情况发生吗?
在正常运行时,CMS GC输出块看起来像这样:
36301.827: [GC [1 CMS-initial-mark: 1856321K(2621330K)] 1879456K(3093312K), 1.7634200 secs] [Times: user=0.17 sys=0.00, real=0.18 secs]
36303.638: [CMS-concurrent-mark-start]
36314.903: [CMS-concurrent-mark: 7.804/11.264 secs] [Times: user=2.13 sys=0.06, real=1.13 secs]
36314.903: [CMS-concurrent-preclean-start]
36314.963: [CMS-concurrent-preclean: 0.037/0.060 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
36314.963: [CMS-concurrent-abortable-preclean-start]
36315.195: [GC 36315.195: [ParNew: 428092K->40832K(471872K), 1.1705760 secs] 2284414K->1897153K(3093312K), 1.1710560 secs] [Times: user=0.13 sys=0.02, real=0.12 secs]
CMS: abort preclean due to time 36320.059: [CMS-concurrent-abortable-preclean: 0.844/5.095 secs] [Times: user=0.74 sys=0.05, real=0.51 secs]
36320.062: [GC[YG occupancy: 146166 K (471872 K)]36320.062: [Rescan (parallel), 1.54078550 secs]36321.603: [weak refs processing, 0.0042640 secs] [1 CMS-remark: 1856321K(2621440K)] 2002488K(3093312K), 1.5456150 secs] [Times: user=0.18 sys=0.03, real=0.15 secs]
36321.608: [CMS-concurrent-sweep-start]
36324.650: [CMS-concurrent-sweep: 2.686/3.042 secs] [Times: uesr=0.66 sys=0.02, real=0.30 secs]
36324.651: [CMS-concurrent-reset-start]
36324.700: [CMS-concurrent-reset: 0.050/0.050 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
就是这样,下一行将是下一个ParNew GC。
当我们使用jmap -histo:live命令强制进行GC时,我们会得到:
48004.088: [CMS-concurrent-mark: 8.012/8.647 secs] [Times: user=1.15 sys=0.02, real=0.87 secs]
(concurrent mode interrupted)
接下来大约有125行以下形式的代码:(一些GeneratedMethodAccessor,一些GeneratedSerializationConstructorAccessor,一些GeneratedConstructorAccessor等)
[Unloading class sun.reflect.GeneratedMethodAccessor3]
其后跟随:
: 1911295K->562232K(2621440K), 15.6886180 secs] 2366440K->562232K(3093312K), [CMS Perm: 52729K->51864K(65536K)], 15.6892270 secs] [Times: user=1.55 sys=0.01, real=1.57 secs]
提前感谢!