Java GC 日志怎样定位暂停时间来源

定位 Java 暂停来源，先找到对应时间窗口中的 Pause 摘要，再关联同一 GC(n) 的阶段明细和 CPU 时间；同时检查安全点记录，分清线程到达安全点的等待与真正停留时间。不能把一个并发标记周期的全部耗时当成应用停止时间，也不能凭“发生过 GC”就认定接口变慢由 GC 引起。

以下示例采用 JDK 25 HotSpot/G1 的统一日志。其他 JVM、收集器和 JDK 版本应以自己的标签、字段和官方文档为准。官方调优入口：https://docs.oracle.com/en/java/javase/25/gctuning/

从有界日志配置开始，不先堆调优参数

统一日志能够把 GC 类型、阶段和安全点记录放在同一观察体系中。它的价值是帮助开发者与运维区分候选原因，不是自动产出根因，更不是采用了某种收集器就能消除暂停。没有本项目的数据，不应声称某一配置会让响应时间下降多少。

在可控发布环境中，为已有应用准备可写日志目录，并把下面的日志选项加入 JVM 启动参数。app.jar 是读者自己的应用包，不是本文提供的程序：

# 相对目录由部署配置提供；日志文件按进程与启动时间区分。
java '-Xlog:gc*=info,safepoint=info:file=logs/gc-%p-%t.log:time,uptime,level,tags:filecount=5,filesize=20M' -jar app.jar

gc* 包含带 GC 标签的多种标签组合；没有星号的匹配范围不同。time 帮助对齐业务记录，uptime 表示 JVM 启动后的时间，%p 与 %t 用于区别进程和启动批次。轮转大小是目标值，不是磁盘占用的严格上限，容量还受当前活动文件等因素影响。

短时诊断需要阶段细节时，可以在受控启动配置中使用下面的 JVM 参数片段：

# 仅为 JVM 参数片段，应放在 -jar 之前；不是独立 shell 命令。
-Xlog:gc*=debug,safepoint=info:file=logs/gc-detail-%p-%t.log:time,uptime,level,tags:filecount=5,filesize=20M

标签组合的可用性可以通过目标 JVM 的 -Xlog:help 了解。本文不在本地启动 JVM、压测应用或采集真实日志；配置是供读者自行采用的例子。

GC 编号关联一次事件，时间关联业务窗口

一组诊断记录包含六个不同对象：时间标记、GC 编号、暂停摘要、阶段明细、CPU 时间和安全点记录。时间标记与 GC 编号属于关联边界；摘要、阶段、CPU 时间属于 GC 记录；安全点记录属于 JVM 停顿记录。

先固定进程、JVM 启动批次和时间窗口，再看 GC 编号。同一个数字在另一 JVM 中没有关联意义。多个实例的日志合并后，如果丢失进程身份，容易把甲实例的暂停与乙实例的慢请求配到一起。

可以在读者自己的日志文件中初步查找关键词，保留匹配行前后的上下文：

# 替换为同一次 JVM 启动产生的日志文件；此命令只筛出候选行。
rg 'Pause|Concurrent|Safepoint|User=|Real=' logs/gc-demo.log

筛选结果不代替完整事件。尤其阶段明细可能没有 Pause 字样，只筛摘要会漏掉工作量分解。跨文件轮转时还需要保留相邻文件，而不是只看最后一个片段。

Pause 是停顿摘要，Concurrent 不是同义词

下面只用两条人为编写的教学记录说明字段，不代表实测性能或完整事件序列：

[18.420s][info][gc] GC(42) Pause Young (Normal) (G1 Evacuation Pause) 384M->96M(768M) 14.200ms
[19.100s][info][gc] GC(43) Concurrent Mark Cycle 218.500ms

第一行的 14.200ms 是这条暂停摘要报告的耗时。384M->96M(768M) 是堆占用前后及堆容量信息，不是耗时分解，更不是对象分配栈。第二行标识并发周期，不能把 218.500ms 直接加进应用停止时间。

G1 的并发标记相关工作中仍存在 Remark、Cleanup 等停顿部分，应分别读取相应 Pause 记录。Mixed 表示回收工作涉及年轻代及选定老年代区域，并不等于 Full GC。看到 Full GC 则需要另查触发原因和此前的回收状况，不宜只按耗时大小命名事件。

阶段和 CPU 时间提示方向，不直接给出代码根因

阶段明细可以帮助区分复制对象、处理堆根、引用处理等工作的耗时。对并行阶段，线程耗时的合计、均值与暂停墙钟时间不是一个口径；多个子阶段还可能有包含关系。不要把所有明细数字相加，声称得到了准确暂停时间。

User、Sys、Real 分别提供用户态、系统态与实际经过时间的线索。并行工作使累计 CPU 时间可能高于墙钟时间；如果实际经过时间明显大于累计 CPU 时间，则需要结合 CPU 调度、容器配额或主机负载继续排查。系统态耗时异常也应联系内存和 I/O 环境判断。

这些只是排查方向。日志没有指出某个业务方法分配了对象时，就不能凭一次 GC 记录归因到该方法。还需适当的分配分析或应用层观测，本篇不把额外工具的结果虚构为已经取得的证据。

安全点等待与 GC 工作属于不同边界

JDK 25 的安全点日志分别报告 到达安全点、安全点内工作、离开安全点与安全点总时间；将这些记录与GC 暂停、业务延迟对齐后，才能区分计时边界。这六个节点分别属于 JVM 计时、GC 计时与应用计时。

Reaching safepoint 较高时，优先查看同步到安全点的开销，不能把整段都算作 GC 复制对象。At safepoint 也可能对应其他 VM 操作，并非每个安全点都是 GC；应同时读取操作名称。这里特别采用 JDK 25 的字段，旧版日志可能另外显示清理项，不能直接套用一份解析模板。

对同一 GC，安全点时间与暂停摘要可能覆盖重叠区间。因此，它们用于解释口径，不应直接累计成两段独立暂停。请求还可能包含排队、锁等待、数据库或网络耗时；时间重叠是归因线索，不是充分证明。

分配压力要看连续样本和回收后的占用

频繁年轻代回收可以提示分配压力，但仅凭堆占用下降幅度，不能准确推算所有对象的分配速率。对比时至少保留相似负载窗口、回收间隔、回收后占用、老年代变化和大对象区域信息；请求量变化后，原始 GC 次数自然也可能变化。

采用日志诊断的收益是缩小候选原因；风险是把相关性当成因果、把采集开销算成原有问题。详细日志增加磁盘写入，采集应限时、可轮转、受权限保护，并保留完整上下文。不要在没有证据时同时改堆大小、年轻代和多项 GC 参数，最后无法判断哪项变化起作用。

用哪些指标判断后续调整

在同等请求量和资源配额下，比较暂停次数、总暂停时间、长尾暂停、回收后占用趋势与应用尾延迟；还要观察吞吐及错误率是否受到影响。G1 的暂停目标不是每次暂停的硬性保证，单条日志低于目标也不能代表整个服务达到延迟要求。

官方命令说明：https://docs.oracle.com/en/java/javase/25/docs/specs/man/java.html
官方 G1 说明：https://docs.oracle.com/en/java/javase/25/gctuning/garbage-first-g1-garbage-collector1.html
官方 G1 调优资料：https://docs.oracle.com/en/java/javase/25/gctuning/garbage-first-garbage-collector-tuning.html

两个相关问题

只统计含 GC 字样的行能得到暂停总量吗？不能。并发记录、阶段明细和暂停摘要可能同时存在，先定义统计口径，避免重复计数。

GC 时间短，业务就不会慢吗？不是。并发回收可能争用资源，业务还存在非 GC 等待。定位暂停来源是性能诊断的一部分，不是对全部业务延迟的解释。

读 GC 日志的关键不是找最大数字，而是先确定数字属于哪一次事件、哪种时间边界，再结合完整窗口判断。先有证据，再选择调整方向。