java - 为什么并发标记和清除 (CMS) 没有清理与 Full GC 相同的内存量？

Question

我的一台生产机器有一个奇怪的问题。它托管了一个执行 CMS（并发标记和扫描）的 Java 应用程序，但它只清理了老一代的一小部分。我怀疑内存泄漏并尝试了堆转储。但是堆转储之前的 Full GC 几乎清理了所有的老年代。发生了什么？我从未见过 Java 垃圾收集的这种行为。通常 CMS 和 Full GC 应该收集大约相同数量的垃圾，现在 CMS 会多保留大约 10GB。

• Java 1.7.0_75
• Linux 美分操作系统 7

GC 日志：

**2016-01-04T07:37:40.196+0000: 431200.698: [GC [1 CMS-initial-mark: 21633423K(27336704K)] 22826703K(30101504K), 4.3910840 secs] [Times: user=4.40 sys=0.01, real=4.39 secs] 
2016-01-04T07:37:44.588+0000: 431205.090: [CMS-concurrent-mark-start]
2016-01-04T07:38:08.718+0000: 431229.220: [CMS-concurrent-mark: 18.213/24.131 secs] [Times: user=126.00 sys=2.22, real=24.13 secs] 
2016-01-04T07:38:08.718+0000: 431229.220: [CMS-concurrent-preclean-start]
2016-01-04T07:38:08.843+0000: 431229.345: [CMS-concurrent-preclean: 0.118/0.125 secs] [Times: user=0.29 sys=0.00, real=0.12 secs] 
2016-01-04T07:38:08.843+0000: 431229.345: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2016-01-04T07:38:13.906+0000: 431234.408: [CMS-concurrent-abortable-preclean: 4.975/5.063 secs] [Times: user=10.18 sys=0.03, real=5.06 secs] 
2016-01-04T07:38:14.001+0000: 431234.503: [GC[YG occupancy: 1312993 K (2764800 K)]2016-01-04T07:38:14.001+0000: 431234.503: [Rescan (parallel) , 4.6981760 secs]2016-01-04T07:38:18.699+0000: 431239.202: [weak refs processing, 0.0002970 secs]2016-01-04T07:38:18.700+0000: 431239.202: [scrub string table, 0.0006900 secs] [1 CMS-remark: 21633423K(27336704K)] 22946417K(30101504K), 4.6993310 secs] [Times: user=105.40 sys=0.36, real=4.70 secs] 
2016-01-04T07:38:18.701+0000: 431239.203: [CMS-concurrent-sweep-start]
2016-01-04T07:38:27.967+0000: 431248.469: [CMS-concurrent-sweep: 9.160/9.267 secs] [Times: user=17.91 sys=0.10, real=9.26 secs] 
2016-01-04T07:38:27.968+0000: 431248.470: [CMS-concurrent-reset-start]
2016-01-04T07:38:28.028+0000: 431248.531: [CMS-concurrent-reset: 0.061/0.061 secs] [Times: user=0.14 sys=0.00, real=0.06 secs]** 
2016-01-04T07:38:30.801+0000: 431251.303: [GC [1 CMS-initial-mark: 21633105K(27336704K)] 23039228K(30101504K), 5.6079370 secs] [Times: user=5.60 sys=0.01, real=5.61 secs] 
2016-01-04T07:38:36.409+0000: 431256.911: [CMS-concurrent-mark-start]
2016-01-04T07:38:54.673+0000: 431275.175: [CMS-concurrent-mark: 17.807/18.264 secs] [Times: user=119.97 sys=1.66, real=18.26 secs] 
2016-01-04T07:38:54.673+0000: 431275.175: [CMS-concurrent-preclean-start]
2016-01-04T07:38:54.799+0000: 431275.301: [CMS-concurrent-preclean: 0.119/0.126 secs] [Times: user=0.25 sys=0.00, real=0.13 secs] 
2016-01-04T07:38:54.799+0000: 431275.301: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2016-01-04T07:39:01.382+0000: 431281.884: [CMS-concurrent-abortable-preclean: 6.478/6.583 secs] [Times: user=12.23 sys=0.06, real=6.58 secs] 
2016-01-04T07:39:01.487+0000: 431281.989: [GC[YG occupancy: 1596183 K (2764800 K)]2016-01-04T07:39:01.487+0000: 431281.989: [Rescan (parallel) , 3.5737630 secs]2016-01-04T07:39:05.061+0000: 431285.563: [weak refs processing, 0.0002690 secs]2016-01-04T07:39:05.061+0000: 431285.563: [scrub string table, 0.0005740 secs] [1 CMS-remark: 21633105K(27336704K)] 23229288K(30101504K), 3.5747910 secs] [Times: user=80.26 sys=0.27, real=3.58 secs] 
2016-01-04T07:39:05.062+0000: 431285.564: [CMS-concurrent-sweep-start]
2016-01-04T07:39:21.895+0000: 431302.397: [CMS-concurrent-sweep: 9.449/16.834 secs] [Times: user=27.52 sys=0.16, real=16.83 secs] 
2016-01-04T07:39:21.895+0000: 431302.397: [CMS-concurrent-reset-start]
2016-01-04T07:39:21.995+0000: 431302.497: [CMS-concurrent-reset: 0.099/0.099 secs] [Times: user=0.23 sys=0.01, real=0.10 secs] 
2016-01-04T07:39:24.104+0000: 431304.606: [GC [1 CMS-initial-mark: **21631742K(27336704K)**] 23455261K(30101504K), 5.6592940 secs] [Times: user=5.67 sys=0.00, real=5.66 secs] 
2016-01-04T07:39:29.764+0000: 431310.266: [CMS-concurrent-mark-start]
2016-01-04T07:39:56.859+0000: 431337.361: [CMS-concurrent-mark: 19.813/27.096 secs] [Times: user=140.17 sys=2.62, real=27.10 secs] 
2016-01-04T07:39:56.859+0000: 431337.361: [CMS-concurrent-preclean-start]
2016-01-04T07:39:57.102+0000: 431337.604: [CMS-concurrent-preclean: 0.152/0.242 secs] [Times: user=0.35 sys=0.00, real=0.24 secs] 
2016-01-04T07:39:57.102+0000: 431337.604: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2016-01-04T07:40:03.016+0000: 431343.518: [CMS-concurrent-abortable-preclean: 5.376/5.914 secs] [Times: user=11.65 sys=0.05, real=5.91 secs] 
2016-01-04T07:40:03.016+0000: 431343.518: [GC[YG occupancy: 2045175 K (2764800 K)]2016-01-04T07:40:03.016+0000: 431343.518: [Rescan (parallel) , 3.4843400 secs]2016-01-04T07:40:06.501+0000: 431347.003: [weak refs processing, 0.0002510 secs]2016-01-04T07:40:06.501+0000: 431347.003: [scrub string table, 0.0006220 secs] [1 CMS-remark: **21631742K(27336704K)**] 23676918K(30101504K), 3.4853760 secs] [Times: user=78.31 sys=0.27, real=3.49 secs] 
2016-01-04T07:40:06.502+0000: 431347.004: [CMS-concurrent-sweep-start]
{Heap before GC invocations=1832 (full 5077):
 par new generation   total 2764800K, used 2166647K [0x00000000bae00000, 0x0000000176600000, 0x0000000176600000)
  eden space 2457600K,  77% used [0x00000000bae00000, 0x000000012e6a4c90, 0x0000000150e00000)
  from space 307200K,  89% used [0x0000000150e00000, 0x0000000161939318, 0x0000000163a00000)
  to   space 307200K,   0% used [0x0000000163a00000, 0x0000000163a00000, 0x0000000176600000)
 concurrent mark-sweep generation total 27336704K, used 21631644K [0x0000000176600000, 0x00000007fae00000, 0x00000007fae00000)
 concurrent-mark-sweep perm gen total 49956K, used 30116K [0x00000007fae00000, 0x00000007fdec9000, 0x0000000800000000)
**2016-01-04T07:40:12.775+0000: 431353.277: [Full GC2016-01-04T07:40:12.775+0000: 431353.277: [CMS2016-01-04T07:40:17.924+0000: 431358.426: [CMS-concurrent-sweep: 9.211/11.422 secs] [Times: user=16.59 sys=0.15, real=11.42 secs] 
 (concurrent mode interrupted): 21631644K->4907878K(27336704K), 39.2467600 secs] 23798292K->4907878K(30101504K), [CMS Perm : 30116K->28023K(49956K)], 39.2468730 secs] [Times: user=39.24 sys=0.05, real=39.25 secs]** 

同一应用程序在另一台使用 Cent OS 5、java 7 的机器上正常运行。

java -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=1581
-Dcom.sun.management.jmxremote.authenticate=false
-Dcom.sun.management.jmxremote.ssl=false -verbose:gc -XX:+PrintGCDetails
-XX:+UseCompressedOops -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC
-XX:+PrintTenuringDistribution -XX:+UseConcMarkSweepGC
-Xloggc:/usr/local/app/logs/current-gc.log -Xms29g -Xmx29g -XX:NewSize=3000m
-XX:SurvivorRatio=8 -XX:CMSInitiatingOccupancyFraction=70
-XX:+UseCMSInitiatingOccupancyOnly
-Dsun.rmi.dgc.client.gcInterval=0x7FFFFFFFFFFFFFFE
-Dsun.rmi.dgc.server.gcInterval=0x7FFFFFFFFFFFFFFE
-cp /usr/local/app/conf:/usr/local/app/app.jar:/usr/local/app/lib/* -Xdebug
-Xrunjdwp:transport=dt_socket,address=8099,server=y,suspend=n
-Dvisualvm.display.name=App -XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/usr/local/app/logs/
-XX:ErrorFile=/usr/local/app/logs/hs_err_pid%p.log
-Djgroups.tcpgossip.initial_host=localhost
-Dlog4j.hostname=host7.company.com com.company.app.service.App

更新：问题仍未解决。我已经尝试了一切：更新操作系统包和内核，将 Java 更新到最新版本 Java 1.7.0_80，回滚应用程序版本，但没有成功。

我也验证了之前的 GC 日志，发现这个问题不是永远存在的。它开始于大约一个月前，在部署之后。

Answer 1

默认情况下，CMS 在 JDK 7 中不卸载类。
您必须指定-XX:+CMSClassUnloadingEnabled，或者更好地切换到 JDK 8。

顺便说一句，如果你jmap不带live参数运行，它不会在创建堆转储之前调用 Full GC。

Answer 2

我怀疑由于堆非常大，您的应用程序中还没有出现对主要收集的需求：既没有终身使用Old Gen也Survivor Space没有用尽。

如果你不这么认为，（即使满足任何一个条件，也没有触发主要收集），分享你 gclog 语句。

不同的注意事项：由于您使用的是大堆，因此首选 G1GC。

编辑：

-XX:CMSInitiatingOccupancyFraction=70 -XX:+UseCMSInitiatingOccupancyOnly 

默认情况下，CMS GC 使用一组启发式规则来触发垃圾收集。这使得 GC 的可预测性降低，并且通常倾向于延迟收集，直到老年代几乎被占用。

-XX:+UseCMSInitiatingOccupancyOnly防止使用 GC 启发式。

-XX:CMSInitiatingOccupancyFraction在应该触发 CMS 时通知 Java VM。

您已将其配置为 70%。如果你的 OldGen [Max heap (29G) - new Gen (3G)] 达到限制的 70%，就会触发 GC。作为 GC 的一部分，会触发第一个次要 GC。如果此时 Minor GC 没有释放足够的空间来分配新对象，则触发 Major GC 或 Full GC。

看看这篇文章了解更多细节。

我发现了另一个相关的 SE 问题：CMS 垃圾收集器 - 它何时运行？. 也看看这个。

Answer 3

因此，您的问题有几个可能的原因，我将首先说明可能的快速解决方案，然后在下面说明您应该考虑长期使用的一些最佳实践。

1. 可能的快速修复：CMS: abort preclean due to time您的日志中的“”条目表明您的 CMS 收集器在最终的stop-the-world完整 GC 阶段之前没有正确调整以完成它的工作。基本上，此日志消息的含义是 preclean 阶段超时，CMS 收集器的进一步步骤无法运行。中止 preclean 阶段的默认时间是 5 秒，从您的日志中似乎就是这种情况。考虑将此时间增加到 10 秒左右，然后观察会发生什么。您应该可以通过添加参数来做到这一点-XX:CMSMaxAbortablePrecleanTime=10000。请参阅Misamitsu 关于CMSMaxAbortablePrecleanTime调整参数的博客条目。另外，根据我从Stas 的关于该主题的博客文章中看到的内容，单位是毫秒，而不是秒。

从长远来看，尝试这些长期的事情：

1. 如果可以，试试 G1GC 收集器。您正在使用 Java 7，因此如果您可以在当前环境中使用，请尝试一下。它适用于大堆的性能。
2. 由于部署而发生这种情况并且回滚不起作用的事实向我表明：
   • 您的整个应用程序（例如 JVM 调整参数）不会作为部署的一部分被捕获，或者...
   • 性能问题的原因与您的应用无关。也许您的两台生产主机与在一台主机上运行的不相关应用程序（例如不同的防病毒版本）之间的差异使您的垃圾收集器的生活变得更加困难。同样，如果可以，请部署到完全相同的硬件和软件。
3. 评估你是否真的需要这么大的堆。请记住，堆越大，垃圾收集器花费的时间越长，无论您是否使用并发收集器（如 CMS）。
4. 你有很多调整参数，我会挑战你需要其中的大部分。考虑运行一个基准实验，您只需删除-XX:NewSize=3000m、-XX:SurvivorRatio=8、-XX:CMSInitiatingOccupancyFraction=70、-XX:+UseCMSInitiatingOccupancyOnly、-Dsun.rmi.dgc.client.gcInterval=0x7FFFFFFFFFFFFFFE和-Dsun.rmi.dgc.server.gcInterval=0x7FFFFFFFFFFFFFFE参数，看看您的情况是否有所改善。

我希望对您有所帮助，如果需要，请评论后续问题。

Answer 4

发生这种情况是有原因的。似乎当您尝试这样做heap dump时正在调用 method dumpHeap()。例如VisualVM在进行堆转储之前触发完整的 GC。

从文档：

void dumpHeap(String outputFile, boolean live) throws IOException

以与 hprof 堆转储相同的格式将堆转储到 outputFile 文件。如果从另一个进程远程调用此方法，则堆转储输出将写入目标 VM 正在运行的机器上名为 outputFile 的文件。如果 outputFile 是相对路径，则它是相对于启动目标 VM 的工作目录的。

参数：

outputFile - 系统相关的文件名

live - 如果 true 只转储活动对象，即其他人可以访问的对象

为什么？

当您尝试查找内存泄漏时，您不想获取没有引用的对象（不是垃圾收集的）。

推荐

我看到一个相当大的堆，可能最好使用G1。

G1 的第一个重点是为运行需要大堆且 GC 延迟有限的应用程序的用户提供解决方案。这意味着大约 6GB 或更大的堆大小，以及低于 0.5 秒的稳定且可预测的暂停时间。

还请查看文档中的推荐部分。