java - 调整 GC (CMS) 的参数

Question

我正在使用 CMS 进行 GC，但是每两个月后 CPU 使用率会非常高。

当情况变得更糟时，有一条 GC 日志，您可能会发现很长的 STW。

3519696.386: [GC [1 CMS-initial-mark: 8617524K(12582912K)] 17105967K(23907584K), 4.9369140 secs] [Times: user=4.94 sys=0.00, real=4.94 secs]
3519701.324: [CMS-concurrent-mark-start]
3519709.419: [CMS-concurrent-mark: 8.096/8.096 secs] [Times: user=16.17 sys=0.00, real=8.09 secs]
3519709.420: [CMS-concurrent-preclean-start]
3519709.442: [CMS-concurrent-preclean: 0.023/0.023 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
3519709.442: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 3519714.691: [CMS-concurrent-abortable-preclean: 3.345/5.248 secs] [Times: user=3.36 sys=0.00, real=5.25 secs]
3519714.692: [GC[YG occupancy: 8489655 K (11324672 K)]3519714.692: [Rescan (parallel) , 8.4072250 secs]3519723.099: [weak refs processing, 0.0000190 secs]3519723.099: [scrub string table, 0.0008130 secs] [1 CMS-remark: 8617524K(12582912K)] 17107180K(23907584K), 8.4081940 secs] [Times: user=65.71 sys=0.15, real=8.41 secs]
3519723.100: [CMS-concurrent-sweep-start]
3519725.451: [CMS-concurrent-sweep: 2.350/2.350 secs] [Times: user=2.36 sys=0.00, real=2.35 secs]
3519725.451: [CMS-concurrent-reset-start]
3519725.478: [CMS-concurrent-reset: 0.028/0.028 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
3519727.480: [GC [1 CMS-initial-mark: 8617522K(12582912K)] 17107229K(23907584K), 4.9378950 secs] [Times: user=4.94 sys=0.00, real=4.94 secs]
3519732.418: [CMS-concurrent-mark-start]

我的 GC 参数:

java -server -Xmx24g -Xms24g -XX:NewSize=12g -XX:MaxNewSize=12g -XX:+HeapDumpOnOutOfMemoryError -XX:MaxDirectMemorySize=24g -XX:+UseConcMarkSweepGC -XX:+UseCMSCompactAtFullCollection -XX:ReservedCodeCacheSize=128m  -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:CMSInitiatingOccupancyFraction=68

我的服务器上安装了9个CPU和64G内存。

能不能帮忙分析一下为什么每个月都变差的关键点？

Answer 1

好的，让我们详细了解一下。我首先要注意的是，所有时间似乎都在用户中，而不是在 sys 中，所以主要怀疑是 JVM 和应用程序。

GC 在老年代触发。容量为12582912K，占用8617524K。总堆使用量为 17105967K，大小为 23907584K。

初始标记大约需要 5 秒。

3519696.386: [GC [1 CMS-initial-mark: 8617524K(12582912K)] 17105967K(23907584K), 4.9369140 secs] [Times: user=4.94 sys=0.00, real=4.94 secs]

据我所知，初始标记仅处理 GC 根。你可以看到这些是哪些 here ，但它花了这么多的事实是奇怪的。我的第一个怀疑是这是受到达安全点时间的影响，所以可能启用:

-XX:+PrintSafepointStatistics –XX:PrintSafepointStatisticsCount=1

并发标记阶段需要8s

3519709.419: [CMS-concurrent-mark: 8.096/8.096 secs] [Times: user=16.17 sys=0.00, real=8.09 secs]

这是在扫描 Activity 对象

Preclean 比较快。

可中止的预清理在 5 秒时被取消，AFAIK 可以使用 CMSMaxAbortablePrecleanTime 进行配置。深入研究这个选项，我发现在这个阶段有少量的收集是可取的，如果不这样做会导致 CMS 中可变的大量暂停。增加 CMSMaxAbortablePrecleanTime，并激活 CMSScavengeBeforeRemark。查看 Jon Masamitsu 发表的这篇文章.

Young generation 8G，重新扫描耗时8s，似乎太多了。同样的评论。安全点。

3519714.692:[GC[YG 占用:8489655 K (11324672 K)]3519714.692:[重新扫描(并行)，8.4072250 秒]3519723.099:[弱引用处理，0.0000190 秒]3519723 .099:[清理字符串表，0.0008130 秒] [ 1 CMS-remark: 8617524K(12582912K)] 17107180K(23907584K), 8.4081940 secs] [Times: user=65.71 sys=0.15, real=8.41 secs]

请注意，年轻一代。这段时间实际增加的大小:8617524K

concurrent-sweep 的最终清理用时 2.35 秒，堆内容似乎没有显着变化。你仍然有大致相同的年轻和堆使用。

所以总结起来我看到两点:

• 您的堆很大，您将达到 CMSInitiatingOccupancyFraction 并触发 CMS，并且似乎有很多时间用于扫描 Activity 对象。无论哪种方式，检查 sizepoint 时间以查看是否可以改进。
• GC 并没有真正收集太多，所以您可能处于以下情况之一:
  • 您想保留大量长期存在的对象(例如:缓存)。在这种情况下，您希望增加 CMSInitiatingOccuppancyFraction(因为您希望旧一代变得非常满)。但也要注意不要提升任何中期或短期对象，因为这些对象最终(在一天或 2 个月内)会导致长时间 GC。那就是:避免在老一代中流失。
  • 您正在生成大量中短期对象，您需要避免升级。减少分配，增加 Eden。

有关您的应用等的任何更多详细信息肯定有助于更好地确定它。我希望能有所帮助。