Java应用GC停顿过长与STW时间飙高的排查方法(GC日志、safepoint安全点与JFR事件定位)

接口P99每隔几分钟抖一次,CPU不高、线程数正常,jstat看GC次数也没涨多少,就是响应时间毛刺很有规律。这种大概率不是GC太频繁,而是单次停顿太长。还有一种更隐蔽的情况:停顿压根不是GC造成的,调堆大小怎么调都没用。

定位这类问题的关键是把停顿拆开看,而不是笼统地加内存、换收集器。下面按实际排查的顺序写。

1、开日志,先分清是不是GC在停

最容易犯的一步错:只开GC日志,看到日志里停顿才200ms,但应用侧明明卡了1秒多。差的那部分时间在别处。有个参数专门打印所有STW的总时长,不管触发原因是GC还是别的VM操作。

# JDK 8
-XX:+PrintGCDetails -XX:+PrintGCDateStamps \
-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime \
-Xloggc:/data/logs/gc.log

# JDK 9及以后用统一日志(JEP 158,随 Java 9.0 引入)
-Xlog:gc*,safepoint:file=/data/logs/gc.log:time,uptime,level,tags:filecount=5,filesize=50m

PrintGCApplicationStoppedTime打出来的那行"Total time for which application threads were stopped"是全量STW。拿它跟同一时段GC日志里的pause对比,差得多就说明有别的操作在停线程:偏向锁撤销、类重定义、线程dump、jmap、某些监控agent的堆栈采集。之前遇到过一次,GC日志里最大停顿120ms,StoppedTime那一列却常年400ms往上,最后查出来是监控每分钟跑一次jstack。

2、读GC日志里的停顿构成

G1的一条年轻代停顿长这样:

Pause Young (Normal) (G1 Evacuation Pause) 1234M->800M(2048M), 0.4423 secs

光看这个0.4423秒没用,要看它内部拆成哪几段。加-XX:+PrintGCDetails(JDK 9及以上换成-Xlog:gc+phases=debug)后会打印每个子阶段的耗时。实测里最常拖后腿的是这两个:

Ref Proc,处理弱引用、软引用、虚引用的阶段,默认是单线程的。堆里塞了大量WeakReference(比如某些缓存框架、ThreadLocal没清理)时,这段能到几百毫秒。加-XX:+ParallelRefProcEnabled让它并行,是最划算的一刀。

Termination,GC工作线程之间互相等。某个线程分到的Region特别难啃,其它线程干完只能干等,日志里会看到某几个线程的耗时明显比别的高。

-XX:+UseG1GC -XX:+ParallelRefProcEnabled -XX:MaxGCPauseMillis=200 \
-Xlog:gc*,gc+phases=debug,safepoint:file=/data/logs/gc.log:time,uptime:filecount=5,filesize=50m

MaxGCPauseMillis的默认值就是200,写不写都一样,它是个目标不是承诺。真正决定单次停顿的是存活对象量和Region分布。

3、安全点(safepoint)造成的停顿

如果GC日志里的时间加起来对不上StoppedTime,就要看安全点了。开启安全点统计:

-XX:+UnlockDiagnosticVMOptions \
-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 \
-XX:+SafepointTimeout -XX:SafepointTimeoutDelay=500

输出长这样:

vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop]
155623.484: RevokeBias [ 1595 0 0 ] [ 0 0 127 7 0 ] 0

看sync和vmop两列:sync是让所有线程走到安全点花的时间,vmop是操作本身。上面这行sync是127ms、vmop是0,说明操作本身几乎不耗时,全耗在等线程停下来。

SafepointTimeoutDelay的默认值是10000毫秒,排查时调到500才抓得住。触发后日志里会打出"Timeout detected when waiting for threads to stop"以及具体哪个线程没停住。

见过两种典型成因。一种是偏向锁撤销,日志里RevokeBias刷屏,偏向锁在JDK 15.0起默认关闭并标记废弃(JEP 374),所以Java 15.0、17.0、21.0、25.0这套新版本上基本见不到了,反倒是跑在JDK 8.0、11.0上的老服务会撞见。另一种是可数循环,JIT把循环里的安全点轮询优化掉了,一个跑很久的for循环迟迟不响应暂停请求,改成long索引或者加-XX:+UseCountedLoopSafepoints可以缓解。

4、用JFR录一段,看事件而不是猜

命令行工具只能抓瞬时值,抖动的毛刺容易漏掉。JFR一次性录几分钟更省事。JFR自JDK 11.0起开源并默认可用(JEP 328),也回移植到了Java 8.0的后期更新版本。

jcmd <pid> JFR.start name=p1 settings=profile duration=120s filename=/tmp/p1.jfr
jfr summary /tmp/p1.jfr
jfr print --events GCPhasePause,SafepointBegin,ExecuteVMOperation /tmp/p1.jfr

重点看三个事件:jdk.GCPhasePause给出每次GC各阶段的精确耗时,jdk.SafepointBegin配jdk.SafepointEnd能算出非GC的停顿,jdk.ExecuteVMOperation会直接写出触发安全点的原因(ThreadDump、RevokeBias、HeapDumper之类)。录完把jfr文件丢进JDK Mission Control,图形界面里按事件时长排序,最贵的那几个一目了然。

5、容器环境的额外注意

JVM从JDK 10.0起默认开启UseContainerSupport(Java 8.0的8u191之后也有),堆和GC线程数会按cgroup的限制来算。给容器设了CPU limit为1,ParallelGCThreads可能就被算成1,一次GC要干原本8个线程的活,停顿自然翻几倍。用-XX:ActiveProcessorCount=4显式指定能绕开这个推算,或者在K8s里把CPU limit调大、只留request。

另外容器里跑jstat要小心,它看到的是宿主机视角的部分指标,OU(老年代已用)这种还能看,但涉及CPU_columns的就别信了。

6、几种形态的对应关系

停顿频繁但每次很短(50ms以内):分配速率太高,年轻代被撑小了,看Eden的回收间隔,适当放大堆或者-XX:G1NewSizePercent(默认5)。

停顿偶尔一次特别长(几秒):先查Humongous对象,G1里超过Region一半大小的对象会被当成巨型对象单独分配,Region默认按堆大小自动推算,也可以-XX:G1HeapRegionSize=16m固定。大数组、大字符串是常客。

停顿时长忽高忽低、GC日志对不上:回到第3步查安全点,再顺手确认一下有没有开swap,NUMA机器上还要看有没有跨节点访问。

每次停顿都很规律地出现在整分整秒:十有八九是外部动作,System.gc()或者定时任务,加-XX:+DisableExplicitGC把显式调用挡掉再说。

7、几个长期开着的诊断参数

-Xlog:gc*,safepoint:file=/data/logs/gc.log:time,uptime:filecount=5,filesize=50m
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/dump
-XX:NativeMemoryTracking=summary
-XX:ErrorFile=/data/logs/hs_err_%p.log

这些开销很小,生产环境常开不亏。真出问题的时候,有没有日志是两回事。

数据截至2026年10月,涉及的版本号为Java 9.0、11.0、15.0、17.0、21.0、25.0与JDK 8.0、10.0、11.0.32、17.0.20、21.0.12、25.0.4等当前主流小版本。