【翻译】JMV GC 停顿时间过长问题排查

Posted 2023-05-07

参考技术A

较短的时间停顿是很多企业应用程序运行时最主要的目标，尤其对于一些过长的响应延迟可能会导致事务超时的事务系统。对于运行在JVM上面的一些系统，垃圾回收（GC）有时会造成较长时间的停顿。
在本文中，我会介绍几种我们可能会遇到的GC导致长时间停顿的场景，并分析我们应该如何诊断和排查这些问题。

下面是应用程序运行时可能会导致GC长时间停顿的几种场景。

Java 堆中的碎片可能会引起频繁的GC活动，并且有可能引起GC长时间停顿。这种情况在CMS垃圾收集器并发收集时老年代空间没有启用碎片压缩时出现的可能性更大一点。
CMS垃圾收集器工作时，由于老年代中存在碎片，年轻代收集时会遇到 “promotion failures” 问题，进而引起 “Concurrent Mode Failure” 失败，最终会触发比并发收集耗时更长的 Full GC 的 stop-the-world 行为。
这些碎片可能会导致直接在老年代分配对象失败，因而引起 Full GC ，尽管老年代还有很多剩余空间。频繁的碎片导致对象分配失败会造成频繁的 Full GC ，从而从总体上增加了应用的停顿时间。
下面这段CMS收集器的日志显示出在老年代有大量的碎片，导致新生代回收时出现 “promotion failures” 异常，并且引起CMS回收时 “Concurrent Mode Failure” 。进而引起一次耗时达到17.1365396s的 Full GC 。

应用程序停顿的时间总共有17.5730653s。

有些时候垃圾回收期间发生的一些系统操作也会引起GC停顿时间变长，比如swap空间交换或者网络活动。这些都有可能导致几秒到几分钟的停顿。
如果你的系统配置了使用swap空间，那么操作系统就会把JVM进程一些不活跃的空间转移到虚拟内存，以便可以释放内存空间给当前进程的活跃线程或系统的其他进程。由于需要操作速度比物理内存慢很多的硬盘，因此swap空间交换是代价非常昂贵的操作。所以，如果在GC期间系统需要swap空间交换，那么GC就会持续更长的时间。
下面是一段新生代GC持续了29.47s的日志：

相应的系统 ‘vmstat’ 命令在03:58输出的日志如下：

这次 Minor GC 持续了约29s。相对应的在此期间系统 ‘vmstat’ 命令输出信息显示系统可用的swap空间减少了差不多600M。这意味着在GC期间一些当前进程非必须的内存页从物理内存中被移到了swap空间。
从上面的信息可以看出，系统的物理内存不够所有运行在系统上面的进程使用。解决的方式就是运行尽量少的进程，同时增加更多的物理内存。上面的日志展示永久代配置的最大使用空间是9G，但是仅有1.8G使用了物理内存。因此有效的解决方式是减少堆空间的大小，减少物理内存的压力，尽量避免或者减少swap空间的交换活动。
除了swap空间交换，我们也要监控在GC期间是否有IO操作或者网络活动。这两项可以使用 ‘iostat’ 和 ‘netstat’ 工具监控。同样使用 ‘mpstat’ 工具输出CPU统计信息观察GC停顿期间是否有可用的CPU资源也非常有用。

如果应用程序占用的空间超过我们为JVM设置的最大堆空间，那么就会导致频繁的GC操作。因为堆空间过小，为对象分配空间的请求失败，JVM就会调用GC操作，释放空间。但是由于每次GC并不能够释放足够的空间，因此越来越多的对象分配失败的请求会引起更多的GC调用。
对应用程序而言， Full GC 会引起更长的应用停顿。如下面的日志所示，因为永久代空间基本已经满了，所以在永久代分配对象的操作失败，触发了一次 Full GC ：

类似的因老年代剩余空间过小导致的对象在老年代分配失败或者 “promotion failures” 也会触发频繁的 Full GC 。
这种问题的解决方案就是根据应用平均使用空间的大小合理配置JVM堆的大小。

JVM的一些bug也会引起GC长时间停顿，比如下面列出的一些JVM bug就有可能造成Java程序长时间的GC停顿：

如果你正在运行的JVM版本包含以上bug，请升级到其他修复版本。

请检查一下是否有显示调用系统GC的操作。应用程序或者第三方模块的某些类对 System.gc() 方法的调用会引起 stop-the-world 的 Full GC 操作。这些显示的系统GC调用也会造成长时间停顿。

如果你正在使用RMI框架，并观察到有固定频率的 Full GC 发生，那么就是这些RMI框架的实现类在定时触发 System.gc() 方法调用。触发间隔可以通过下面两个系统配置项配置：

这两个配置项的默认值在JDK 1.4.2版本和5.0版本是60s，在JDK 6及以后的版本中，都是1小时。如果你想禁止因 System.gc() 方法调用引起的 Full GC 操作，可以在应用运行时增加这个 -XX:+DisableExplicitGC JVM参数。

1、收集GC日志时配置上这些参数： -XX:+PrintGCDetails -XX:+PrintHeapAtGC -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime 。如果是CMS收集器，再增加 -XX:PrintFLSStatistics=2 这个配置。
这些GC日志可以给我们有关GC停顿的频率和性质的详细信息，即他们可以告诉我们GC停顿是发生在新生代还是老年代，以及停顿发生的频率等相关信息。

2、用Solaris和其他Linux平台上的 ‘iostat’ 、 ‘netstat’ 、 ‘mpstat’ 、 ‘vmstat’ 等系统工具或者Windows操作系统上的 进程监视器 和任务管理器从全局监控系统的运行情况。

3、使用 GCHisto 工具使GC日志可视化，发现哪些GC操作耗时较长，并发现这些GC的一些共性。

4、通过GC日志发现是否在Java堆中存在碎片。

5、监控配置的Java 堆空间是否够应用程序使用。

6、检查你的应用程序是否运行在包含已知的会导致GC长时间停顿的bug的JVM版本。如果是，就升级到新的修复版本。

GC问题排查常用命令-jstat

jstat查看GC的常用命令

jstat [ generalOption， outputOptions vmid， [ interva，count ]

参数：
generalOption: 一般使用-gcutil查看GC情况
vmid: 虚拟机进程号，即当前运行的java进程号
interval: 间隔时间，单位为秒或毫秒
count: 打印次数，如果缺省则打印无数次

1、查询GC总体使用情况

jstat -gcutil 23484 1000 5

结果说明：

S0: 新生代中Survivor space 0区已使用空间的百分比
S1: 新生代中Survivor space 1区已使用空间的百分比
E: 新生代已使用空间的百分比
O: 老年代已使用空间的百分比
M：元数据区使用比例
CCS：压缩使用比例
YGC: 从应用程序启动到当前，发生Yang GC 的次数
YGCT: 从应用程序启动到当前，Yang GC所用的时间【单位秒】
FGC: 从应用程序启动到当前，发生Full GC的次数
FGCT: 从应用程序启动到当前，Full GC所用的时间
GCT: 从应用程序启动到当前，用于垃圾回收的总时间【单位秒】

2、垃圾总体回收统计

jstat -gc 18528 1000 5

• S0C：第一个幸存区的大小
• S1C：第二个幸存区的大小
• S0U：第一个幸存区的使用大小
• S1U：第二个幸存区的使用大小
• EC：伊甸园区的大小
• EU：伊甸园区的使用大小
• OC：老年代大小
• OU：老年代使用大小
• MC：方法区大小
• MU：方法区使用大小
• CCSC:压缩类空间大小
• CCSU:压缩类空间使用大小
• YGC：年轻代垃圾回收次数
• YGCT：年轻代垃圾回收消耗时间
• FGC：老年代垃圾回收次数
• FGCT：老年代垃圾回收消耗时间
• GCT：垃圾回收消耗总时间

3、新生代垃圾回收统计

jstat -gcnew 18528 1000 5

• S0C：第一个幸存区大小
• S1C：第二个幸存区的大小
• S0U：第一个幸存区的使用大小
• S1U：第二个幸存区的使用大小
• TT:对象在新生代存活的次数
• MTT:对象在新生代存活的最大次数
• DSS:期望的幸存区大小
• EC：伊甸园区的大小
• EU：伊甸园区的使用大小
• YGC：年轻代垃圾回收次数
• YGCT：年轻代垃圾回收消耗时间

4、堆内存统计

jstat -gccapacity 18528 1000 5 //整体统计
jstat -gcnewcapacity 18528 1000 5 //新生代统计
jstat -gcoldcapacity 18528 1000 5 //老年代统计

NGCMN：新生代最小容量
NGCMX：新生代最大容量
NGC：当前新生代容量
S0C：第一个幸存区大小
S1C：第二个幸存区的大小
EC：伊甸园区的大小
OGCMN：老年代最小容量
OGCMX：老年代最大容量
OGC：当前老年代大小
OC:当前老年代大小
MCMN:最小元数据容量
MCMX：最大元数据容量
MC：当前元数据空间大小
CCSMN：最小压缩类空间大小
CCSMX：最大压缩类空间大小
CCSC：当前压缩类空间大小
YGC：年轻代gc次数
FGC：老年代GC次数