调整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和应用程序。

气相色谱仪是在老电厂触发的。容量为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] 

AFAIK初始标记只处理GC根。你可以看到这些是here，但事实是它很多很奇怪。我的第一个怀疑是这是由时间来safepoints的影响，所以也许能：

-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] 

这是扫描活物

Preclean比较快。

可中止的预清除在5秒后被取消，AFAIK出现时可用CMSMaxAbortablePrecleanTime配置。挖掘这个选项，我发现在这个阶段进行次要收集是可取的，如果不这样做可能会导致CMS中发生可变的大停顿。增加CMSMaxAbortablePrecleanTime并激活CMSScavengeBeforeRemark。看看这个帖子Jon Masamitsu。

年轻一代在8G和重新扫描了8s，这似乎太多了。再次同样的评论。 safepoints。

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.4081940sec] [Times：user = 65.71 sys = 0.15，real = 8.41sec]

注意，在此期间实际增加的大小为：8617524K

并发扫描的最终清理需要2.35秒，并且堆内容似乎没有实质性改变。你仍然有大致相同的年轻和堆用法。

所以总结我看到两点：

• 你堆大，你就到达CMSInitiatingOccupancyFraction和触发CMS，以及大量的时间似乎对扫描活动对象走了。无论哪种方式，检查尺寸点的时间，看看是否可以改善。
• GC并没有真正收取多少，所以你在这些情况下一个很可能：
  • 你要保持大量的长寿命的对象（例如：高速缓存）。在这种情况下，您想要增加CMSInitiatingOccuppancyFraction（正如您所期望的那样，旧gen会变得非常满）。但是请注意，您不会宣传任何中等或短期的物品，因为这些物品最终（一天或两个月内）会导致漫长的地理信息系统。那就是：避免老流失。
  • 您正在生成大量短暂居中对象，因此您需要避免宣传。减少拨款，增加伊甸园。

任何关于你的应用程序的详细信息，等等肯定会有助于指甲会好些。我希望这会有所帮助。

Answer 2

在你的日志中，我没有看到正常的年轻GC。 CMS Stop-the-World阶段旨在回收年轻空间收集方面的效果。

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] 

这里CMS-initial-mark必须在一个线程中扫描8.6 GiB的年轻空间。如果在年轻的GC年轻人占领空间后将立即援引，那么这个数字会小得多。

对于CMS-remark也是如此。

年轻人有很大的年轻的空间，所以你最终在情况，当你旧的空间更频繁地收集这个年轻的空间。

这里有几个选项来补救

• -XX:CMSWaitDuration=3600000让CMS-initial-mark等待长达一个小时，直到下一个年轻的GC。
• -XX:+CMSScavengeBeforeRemark让CMS-remark强制年轻的收集产生可预测的暂停时间。其中有平行CMS-initial-mark

更多细节

使用最新的Java 7/8是this article可用。