简短形式:CMS 垃圾收集器似乎无法收集越来越多的垃圾;最终,我们的 JVM 被填满,应用程序变得无响应。通过外部工具(JConsole 或 jmap -histo:live
)强制 GC 将其清理一次。
更新:问题似乎与 JConsole 的 JTop 插件有关;如果我们不运行 JConsole,或者在没有 JTop 插件的情况下运行它,该行为就会消失。
(技术说明:我们在 Linux 2.6.9 机器上运行 Sun JDK 1.6.0_07,32 位。升级 JDK 版本并不是真正的选择,除非有不可避免的主要原因。此外,我们的系统未连接到可访问 Internet 的机器,因此 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 分钟左右运行一次完整的 GC;在每次完整的 GC 之后,仍有越来越多的内存在使用中。几个小时后,系统达到稳定状态,旧版 CMS 中大约有 2GB 的已用内存。
这听起来像是典型的内存泄漏,除非我们使用任何强制执行完整 GC 的工具(点击 JConsole 中的“收集垃圾”按钮,或运行 jmap -histo:live
等),旧代突然下降到 ~500MB 使用,我们的应用程序在接下来的几个小时内再次响应(在此期间,相同的模式继续 - 在每次完整的 GC 之后,越来越多的旧代已满。)
需要注意的一件事:在 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
,以及数组code>Hashtable$Entry
(每个的数量大约相同;大约是 HashMap 和 Vectors 的一半)
下面是 GC 输出的一些摘录;我对它们的解释似乎是 CMS GC 正在中止,但没有故障转移到 stop-the-world GC。我是否以某种方式误解了这个输出?有什么东西会导致这种情况吗?
在正常运行时,CMS GC 输出 block 看起来像这样:
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]
提前致谢!
最佳答案
com.sun.jmx.remote.util.OrderClassLoader 在 JMX 的远程层中使用,快速查看代码表明它们是作为 JVM 内部远程请求的解码过程的一部分创建的。这些类加载器的生命周期将与被解码的事物的生命周期直接相关,因此一旦不再有对该事物的任何引用,类加载器就可以被释放。
如果在这种情况下这些实例的存在是您使用 JConsole 检查 JVM 中发生的事情的直接结果,我不会感到惊讶。看起来它们只是作为正常操作的一部分被 GC 清理掉了。
我猜 JMX 实现中可能存在错误(在相对较新的 JVM 中似乎不太可能),或者您有一些自定义 MBean 或正在使用导致问题的某些自定义 JMX 工具。但最终,我怀疑 OrderClassLoader 可能是一个转移注意力的问题,问题出在其他地方(GC 损坏或其他泄漏)。
关于Java ConcurrentMarkSweep 垃圾收集器不清除所有垃圾,我们在Stack Overflow上找到一个类似的问题: https://stackoverflow.com/questions/3873635/