Java CMS被忽略，却得到了Full GC

Question

我正在运行一个使用CMS作为终生收集器的Java服务器。在负载测试下，我看到大约每1秒就会进行一次年轻代收集和每5分钟进行一次（并发）老年代收集。这很好。

当我以约1/2容量的实际流量运行时，我大约每4秒就会进行一次年轻代收集和每7分钟进行一次（并行、停止所有进程的）老年代收集。为什么JVM决定执行完整的停止所有进程收集而不是使用CMS收集器？

从gc.log中可以看到运行"Full GC"并花费超过3秒的情况。这里没有并发模式失败。没有明确要求进行收集。

1350.596: [GC 1350.596: [ParNew
Desired survivor size 119275520 bytes, new threshold 3 (max 3)
- age   1:   34779376 bytes,   34779376 total
- age   2:   17072392 bytes,   51851768 total
- age   3:   24120992 bytes,   75972760 total
: 1765625K->116452K(1864192K), 0.1560370 secs] 3887120K->2277489K(5009920K), 0.1561920 secs] [Times: user=0.40 sys=0.04, real=0.16 secs] 
1355.106: [GC 1355.107: [ParNew
Desired survivor size 119275520 bytes, new threshold 3 (max 3)
- age   1:   44862680 bytes,   44862680 total
- age   2:   20363280 bytes,   65225960 total
- age   3:   16908840 bytes,   82134800 total
: 1747684K->123571K(1864192K), 0.1068880 secs] 3908721K->2307790K(5009920K), 0.1070130 secs] [Times: user=0.29 sys=0.04, real=0.11 secs] 
1356.106: [Full GC 1356.106: [CMS: 2184218K->1268401K(3145728K), 3.0678070 secs] 2682861K->1268401K(5009920K), [CMS Perm : 145090K->145060K(262144K)], 3.0679600 secs] [Times: user=3.05 sys=0.02, real=3.07 secs] 
1361.375: [GC 1361.375: [ParNew
Desired survivor size 119275520 bytes, new threshold 3 (max 3)
- age   1:   33708472 bytes,   33708472 total
: 1631232K->84465K(1864192K), 0.0189890 secs] 2899633K->1352866K(5009920K), 0.0191530 secs] [Times: user=0.19 sys=0.00, real=0.02 secs] 
1365.587: [GC 1365.587: [ParNew
Desired survivor size 119275520 bytes, new threshold 3 (max 3)
- age   1:   33475320 bytes,   33475320 total
- age   2:   22698536 bytes,   56173856 total
: 1715697K->67421K(1864192K), 0.0229540 secs] 2984098K->1335822K(5009920K), 0.0231240 secs] [Times: user=0.25 sys=0.00, real=0.03 secs] 

以下是JVM标志：

-server -Xss256K -Xms5120M -Xmx5120M -XX:NewSize=2048M -XX:MaxNewSize=2048M
-XX:SurvivorRatio=7 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC
-XX:+CMSParallelRemarkEnabled -XX:CMSInitiatingOccupancyFraction=80
-XX:+UseCMSInitiatingOccupancyOnly -XX:CMSFullGCsBeforeCompaction=1
-XX:SoftRefLRUPolicyMSPerMB=73 -verbose:gc -XX:+PrintGCDetails
-XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -Xloggc:logs/gc.log
-XX:MaxPermSize=256m -XX:PermSize=256m -XX:MaxTenuringThreshold=3

- Brian White

---

有趣的事情...大约2800秒（+/- 200s）后，CMS再次开始使用。通常会有1或2次尝试被中止并显示“并发模式中断”，之后所有CMS都成功了。此期间流量没有改变。2415.457 - 完全GC ...年轻的收集... 2684.320 - CMS-initial-mark（日志中的第一个CMS-mark） 2684.436 - 完全GC（并发模式中断） ...年轻的... ...另一个CMS中断... ...年轻的... 3224.451 - CMS-initial-mark 3234.855 - 年轻的 3230.254 - CMS-remark 3231.972 - CMS-reset（完成） ...一切顺利... - Brian White

根据CMS代码，“并发模式中断”消息是由于(a)GCCause::is_user_requested_gc或(b)GCCause::is_serviceability_requested_gc。这意味着原因是(a)_java_lang_system_gc或_jvmti_force_gc，或者(b)_jvmti_force_gc，_heap_inspection或_heap_dump。看起来同样的事情可能是Full GC和中断的来源，但是这些都不应该发生。 - Brian White

如果您感兴趣，这是一台服务器的GC日志文件的前8000秒。 - Brian White

好的，听我说...如果我降低Tenured GC启动的阈值，无论是通过降低占用率还是堆内存量，那么它就从一开始就使用CMS收集器。在CMS中是否有什么机制，如果GC之间的间隔时间太长，会回到Parallel收集器？ - Brian White

还有使用 JNI 吗？JNI 的关键部分可能会延迟/影响 GC。或者在启动时存在某些分配行为（例如非常大的对象），导致它执行一些缓慢的路径分配？ - Matt

Answer 1

如果你的幸存者空间不够大，就会触发Full GC。（它似乎在抱怨幸存者比例）

要么你需要降低幸存者比例，要么更好的解决方案是增加NewSize，这样来自伊甸园空间的对象就会更少地幸存。我有一个6GB的伊甸园空间 ;)

- Peter Lawrey

---

Survivor空间通常会保留大约4-6个循环，但由于它在每个循环中不会减少数量，我将其限制为3个循环，以减少不必要的memcpy数量。 - Brian White

顺便提一下，我的Eden大小被选择为在满负荷下每1秒钟不超过一次进行垃圾回收，并且平均停顿时间为50毫秒。请求通常在不到50毫秒的时间内得到回答，99.9%的请求在250毫秒以下完成。 - Brian White

顺便说一句：只要创建最少的对象，Eden空间就足够使用一整天。每天凌晨5点进行一次完全GC，没有任何次要GC。;) 响应时间在很大一部分时间内都低于0.1毫秒。 - Peter Lawrey

它相当于每个服务器大约20个/秒。它可以处理高比例的请求而不创建任何对象。 - Peter Lawrey

太好了。不幸的是，我正在运行的程序会创建很多东西（尽管我正在与开发人员合作来减少这些）。另外，我“说错了”……它是每秒100个请求（每个4核服务器 - 不是我运行过的最有效的Java二进制文件）；10个服务器。 - Brian White

Answer 2

我记得去年在调整大堆以避免完全GC时，看到了类似的现象。我认为您可能需要减小eden的大小。与tenured generation相比，它相当大。

我认为可能发生的情况是，您的1/2速度流量使更多的eden同时变旧，而在全速度下它们不会存活。这意味着更多的eden需要一次性移动到tenured，如果此时不适合，则可能触发完全GC以腾出空间。

供参考，以下是我们现在用于6GB到24GB堆的设置：

-XX:NewRatio=4 -XX:SurvivorRatio=8 -XX:+UseCompressedOops
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+DisableExplicitGC  
-XX:+UseCMSInitiatingOccupancyOnly -XX:+CMSClassUnloadingEnabled  
-XX:+CMSScavengeBeforeRemark -XX:CMSInitiatingOccupancyFraction=68
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:logs/gc.log

这与你的代码非常相似。使用所有比率的好处在于，您可以轻松更改堆大小，并且它（通常）会适当地缩放。另一个注意点是，-XX：+ UseCompressedOops 通常可以通过将64位寻址减少到32位来使用40％的内存（仅适用于32GB以下）。

- WhiteFang34

---

由于无法将年轻对象提升到终身空间，触发了Full GC，它将显示为日志中的“并发模式失败”，但实际上并不存在。我以前见过很多这样的情况；occupancy=80是仔细调整的结果。我的请求几乎总是在<250ms内得到响应，因此大部分Eden空间立即被丢弃，不到10%的空间被复制到survivor空间。大约四分之一到一半的空间在下一个循环中被抛弃，之后无论允许多少次复制，都不会再减少太多（因此TenuringThreshold=3）。不到5%的Eden空间被提升到终身空间。 - Brian White

显然我说得太早了。将我的“占用分数”降低到60确实停止了这个问题。也许除非JVM自启动以来尝试了至少一次CMS收集（尽管我不明白为什么它没有），否则它不被视为“并发模式失败”。即使是JVM内部的计数器也没有将其计算为这样，无论是否有日志消息。现在...为什么将15-30MB移动到3G的新老年代空间时，70的占用率会出现问题，而65则可以正常工作呢？ 30MB只占3G的1％。 - Brian White