生产环境里突然遇到接口响应极慢,CPU飙高,甚至请求直接超时,很多同学第一反应就是“服务挂了”。其实大概率不是你代码写错了,而是垃圾回收,特别是Full GC在“偷走”你应用的线程。我干过不少Java服务,今天就拿一次真实的排查经历,和大家聊聊怎么从GC日志一步步找到根因,然后调整堆内存配置把问题解决。
一、故障现象:一种让人抓狂的“假死”状态
那天下午,运营同事说后台页面打开转圈,接口耗时从几十毫秒涨到十几秒,依次重启也没用。我去服务器上看了一下,进程还在,线程栈也能拿到,但很多业务线程都卡在GC相关的状态上,比如Object.wait或者GC pause。用top -H看线程CPU,发现大部分CPU时间都花在JVM的GC线程上。这时候基本可以断定:发生了频繁的Full GC。
Full GC是一次全局范围的垃圾回收,要停止所有业务线程(也就是Stop The World),本来一次几百毫秒还能接受,但如果频繁触发,你的服务就会像被人按住暂停键,一会一顿。这种卡顿不是网络问题,也不是慢SQL,纯粹是JVM在收拾内存垃圾时打扰了你的业务。
二、找证据:拿到GC日志才是第一步
遇到这种情况,别急着猜,先看证据。日志就是最好的证据。你需要确认自己服务的JVM有没有开启GC日志。如果之前启动了,直接去日志文件里搜“Full GC”就好;如果没有,那只能先加参数重启,或者用jstat等工具观察在线状态,但最好还是在启动参数里加上GC日志,这样下次出问题就知道怎么查了。
2.1 开启GC日志的JVM参数
通常我们会加上下面这些参数,让JVM把每次垃圾回收的详细情况打印出来:
# 技术栈:Java
# 这是一组常用的JVM参数,用于打印GC详细日志到文件
-Xloggc:/data/logs/gc.log # 指定GC日志输出文件
-XX:+PrintGCDetails # 打印详细GC信息
-XX:+PrintGCDateStamps # 打印日期时间戳,方便对应业务时间
-XX:+PrintGCApplicationStoppedTime # 打印应用停顿时间
-XX:+PrintGCApplicationConcurrentTime # 打印应用并发执行时间
只要加上这些,比如用java -jar启动时全部带上,JVM就会乖乖地把每一次年轻代、老年代和Full GC都记录到gc.log里。
2.2 看一段真实的GC日志
下面是我从当时生产环境里截取的一段GC日志,为了演示,我加了注释说明每个字段的意思:
// 技术栈:Java
// 这是一段通过-XX:+PrintGCDetails输出的GC日志(内容经过简化,但格式真实)
2024-11-05T14:32:15.123+0800: 21678.234: [Full GC (System.gc()) 21678.234: [CMS: 129468K->128052K(131072K), 1.9874560 secs] 131076K->129410K(1992288K), 2.0845560 secs] [Times: user=2.11 sys=0.02, real=2.08 secs]
// 从这行可以看出:这是一个Full GC,原因是System.gc()被调用(或者外部触发)
// 老年代(CMS)回收前占129468K,回收后还有128052K,基本没释放多少内存,因为老年代已经满了
// 整个堆从131076K到129410K,也就降了不到2MB,而总堆大小是1992288K
// 最关键的是,这个GC停了2.08秒,这2秒钟所有业务线程全部暂停
看到没?这一行日志就暴露了两个关键点:第一,Full GC频率很高;第二,每次Full GC耗时很久;第三,回收之后老年代内存并没有明显下降。这说明什么?说明老年代已经“满”到几乎没有空间可回收,或者有大量对象根本回收不掉。
三、堆内存配置:真相往往藏在这里
Full GC一般发生在老年代内存不足时。老年代存的东西是从年轻代熬过多次垃圾回收后晋升过去的对象,还有一些大对象直接进入老年代。如果你的堆内存设置不合理,比如-Xmx设得太小,或者新生代与老年代比例不对,就很容易让老年代早早打满,然后JVM一次次启动Full GC。
3.1 用jstat看看运行时内存分布
除了看日志,我们还可以用JDK自带的jstat命令,实时观察进程的内存使用和GC情况。假设我们的Java进程号是1234,可以这样看:
# 技术栈:Java
# jstat -gcutil 统计垃圾回收堆使用情况,每隔1秒输出一次
jstat -gcutil 1234 1000
# 输出结果示例:
# S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
# 0.00 50.00 80.00 99.98 92.00 85.00 12345 456.789 678 1234.567 1691.356
这一行的解释如下:
S0、S1:两个Survivor区当前使用比例。E:新生代中的Eden区使用比例。O:老年代使用比例。这里看到99.98%,基本满的。M:元空间使用比例。YGC:年轻代GC次数。YGCT:年轻代GC总耗时。FGC:Full GC次数。678次,不少了。FGCT:Full GC总耗时,1234秒,平均每次2秒左右。GCT:所有GC总耗时。
看到O接近100%,FGC还在不断增加,基本上可以实锤是老年代太挤导致Full GC疯狂发生。
3.2 看堆配置参数
用jcmd VM.flags可以查看当前JVM生效的参数,确认一下我们到底给堆设了多大:
# 技术栈:Java
# 查看进程1234当前的JVM参数
jcmd 1234 VM.flags
# 输出会包含类似下面的内容(已删减):
# -Xms2048m -Xmx2048m -XX:NewSize=512m -XX:MaxNewSize=512m -XX:SurvivorRatio=8
# 这说明堆大小固定2GB,新生代512MB,老年代1.5GB
我那次遇到的配置是-Xms2g -Xmx2g,这看起来没毛病,但问题在于服务本身用了很多缓存,并且有个本地内存存储了大量业务数据,导致老年代快速填满。后来又查了G1或者CMS的选择,发现用的还是老旧的CMS回收器,它对大堆和碎片化处理得并不好。
四、一个实战例子:从Full GC到平稳运行
下面我用一个模拟的Spring Boot应用,完整演示一遍排查和调整过程。这个应用的业务很简单,就是往一个静态List里不断加数据,模拟内存增长。
4.1 启动参数先故意设小一点
我们把堆内存设置得不足,然后启动应用:
# 技术栈:Java
# 启动一个Java应用,故意把堆设成512MB,并开启GC日志
java -Xms512m -Xmx512m -XX:NewSize=128m -XX:MaxNewSize=128m \
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/data/gc.log \
-jar demo-0.0.1-SNAPSHOT.jar
4.2 运行一段时间后查看GC日志
应用跑一会儿,我们可以看到gc.log里出现了这样的记录:
// 技术栈:Java
// 模拟运行后的GC日志片段
2024-11-05T15:00:01.123+0800: 100.123: [GC (Allocation Failure) 2024-11-05T15:00:01.123+0800: 100.123: [ParNew: 116582K->14182K(118016K), 0.0289050 secs] 308675K->242591K(507776K), 0.0298820 secs]
// 这是年轻代GC,Eden区满了发生Allocation Failure,耗时28毫秒,还算正常
2024-11-05T15:00:02.150+0800: 101.150: [Full GC (Ergonomics) 2024-11-05T15:00:02.150+0800: 101.150: [CMS: 242382K->240982K(389760K), 2.7654320 secs] 242591K->240982K(507776K), [Metaspace: 33456K->33456K(133120K)], 2.7768540 secs]
// 仅仅过了1秒钟,就发生了Full GC
// 这次Full GC耗费2.77秒,但老年代回收后仍占240MB,基本没降下来
看到没?年轻代GC之后,老年代几乎还是满的。这就导致JVM每隔几秒就要Full GC一次,业务线程大量时间被暂停。
4.3 用jmap查看内存对象分布
为了搞清楚是不是有什么东西占了内存,我们选择在Full GC后马上dump一份堆:
# 技术栈:Java
# 将进程1234的堆内存dump到文件,然后可以用MAT等工具分析
jmap -dump:live,format=b,file=/data/heap.hprof 1234
通过MAT打开堆转储文件,可以看到有一个ArrayList占据了将近400MB。里面的对象是某个订单DTO,数量巨大。继续往下查,发现这个ArrayList被定义成了static,并且一直没有清理。原来是一个生产者不断往里面塞数据,消费者却因为业务异常不再读取。这就是典型的内存泄漏。
4.4 调整代码与堆参数
既然找到了根因,那么先修代码:改成有界队列,并定期清理。然后我们再把堆内存调大一点,毕竟生产环境不可能只给512MB,但也不能盲目调太大,否则一次Full GC的停顿时间会更长。
调整后的启动参数:
# 技术栈:Java
# 将堆调整为2GB,并且明确新生代与老年代比例,使用G1回收器
java -Xms2g -Xmx2g -XX:+UseG1GC -XX:MaxGCPauseMillis=100 \
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/data/gc.log \
-jar demo-0.0.1-SNAPSHOT.jar
这里我们用了G1回收器,它比CMS更适合大堆内存,能通过调节目标停顿时间来控制GC频率,并且把一次Full GC拆分成多次混合回收,尽可能减少长时间停顿。
调整后再看jstat,老年代使用率稳定在40%左右,Full GC次数不再增加,接口响应恢复到毫秒级。修复代码后,再也没有出现频繁Full GC的情况。
五、关联技术:垃圾回收器是怎么配合堆内存的
在排查过程中,你会发现“堆内存配置”和“垃圾回收器选择”是绑在一起的。现代JVM提供了很多回收器,比如:
5.1 CMS
CMS全称Concurrent Mark Sweep,老年代回收器。它的特点是并发标记清理,尽量让大部分工作跟业务线程并行执行,但会产生内存碎片。如果堆比较大,CMS容易出现Concurrent Mode Failure,然后退化成Full GC。我们上面遇到的CMS Full GC就是这样,又慢又频繁。
5.2 G1
G1把这个大堆分成很多Region,然后可以并发地回收一部分Region,不需要一次性回收全部老年代。这样就能把停顿时间控制在可预期范围内,比如-XX:MaxGCPauseMillis=100意思是希望每次GC停顿尽量不超过100毫秒。对于服务器应用,G1通常是比CMS更好的选择。
5.3 ZGC
ZGC更进一步,几乎不暂停业务线程,适合超大堆和极高响应要求。但配置相对复杂,且不是所有版本都支持。如果你的应用要求几十毫秒内完成事务,ZGC可以帮忙。
拿我们刚才的案例来说,如果直接用CMS + 2G堆,内存碎片可能会让Full GC仍然频繁;换成G1后,它能够用Mixed GC一边回收年轻代一边回收部分老年代,明显减少了整体停顿。
六、常见误区和注意事项
很多开发者一遇到Full GC第一反应是“堆内存不够”,于是把-Xmx调大,结果问题反而更严重。为什么?因为堆越大,Full GC的耗时越长,对吞吐量的影响也越大。调堆内存必须结合业务实际情况:到底有多少对象是存活对象,有多少是垃圾对象,哪些对象占了大头。所以要注意下面几点:
不要盲目调-Xmx。你需要先通过heap dump找到大对象,确认是内存泄漏还是容量配置不足。如果是为了应付突发流量,可以适当加内存,但也要配合回收器调整。
注意对象晋升问题。假如年轻代设置太小,很多大对象会直接进入老年代,老年代一满就Full GC。我们可以用
-XX:PretenureSizeThreshold设置大对象直接进老年代的阈值,但更需要关注是否频繁发生Young GC后晋升。通过gc日志里的desired survivor size可以辅助判断。小心System.gc()。有些框架或代码会主动调用
System.gc(),它会触发Full GC,线上非常危险。最好启动时加上-XX:+DisableExplicitGC禁止显式触发。不过,如果用的是RMI等需要显式GC的框架,要谨慎禁用。用jstat持续观察比一次性日志更直接。我们要关注老年代使用率增长曲线,如果刚启动就快速上涨,说明可能有问题。
不同容器的内存限制。在Docker或Kubernetes里,JVM可能检测不到宿主机内存限制,导致-Xmx设置过大,被操作系统杀掉。所以务必在容器内显式设置
-XX:MaxRAMPercentage或者物理堆大小。别忘了元空间。元空间(Metaspace)满了也会触发Full GC,虽然不会通常不导致堆内存溢出,但日志里要留意
Metaspace那一列。
七、文章总结
频繁Full GC导致服务卡顿,本质上是一次“内存拆迁”。你要是闷头猜测,很难猜准。正确路径是:先通过GC日志或jstat确认是否Full GC频繁,然后结合堆dump找内存占用大头,最后决定是修代码还是调配置。垃圾回收器选择也很重要,G1基本可以替代CMS成为首选,如果你的硬件资源富余且追求极致响应,ZGC更值得考虑。堆内存参数没有一劳永逸的方案,必须在观察中不断调整,找到那种“内存够用,GC安静”的状态。每次排查完,顺手把GC日志保留好,把启动参数记录下,下次再遇到类似问题,你就有了一份一手证据。
评论
围绕“Java生产环境频繁Full GC导致服务卡顿?从GC日志分析到堆内存配置的完整排查路径”参与讨论