java

《Java 虚拟机原理与性能调优》6.1 GC 日志解析：统一日志、停顿指标与分配失败

一行 GC(9) Pause Young (Mixed) 431M->313M(512M) 0.964ms 里每个字段是什么意思？本节用本机 12 秒真实日志拆字段、讲标签、复现 Evacuation Failure，并给出解析停顿的 gc-summary.py。

Leeting Yan 2026-10-27 11 分钟阅读 5312 字

本节目标：把一行 GC 日志拆到每个字段，知道哪个标签能回答哪个问题，并能用脚本把几万行日志变成可比较的停顿指标。
适用版本：JDK 25（Temurin 25.0.5）。统一日志（JEP 158 / 271）自 JDK 9 起取代 -XX:+PrintGCDetails。

承接的问题

libraryd 的批量借阅导出接口在夜间跑批时出现 P99 尖刺：监控显示 800 ms，但 CPU 利用率只有 40%，数据库慢查询日志为空。值班同学的第一反应是「GC 停顿」，第二反应是「把堆调大」。

两种反应都可能错。要判断 GC 是不是原因，需要回答：

尖刺发生的 30 秒里，有没有超过 800 ms 的 GC 停顿？
如果没有，堆曲线为什么在涨？
如果有，是 Young GC、Mixed GC 还是 Full GC？

这三个问题都只能从 GC 日志回答，不能靠 jstat 的累计值。jstat -gcutil 给的是百分比和累计次数，看不出单次停顿；GarbageCollectorMXBean 的 getCollectionTime() 是累计毫秒，也不区分单次。

本机为 Apple M1 Pro / 10 核 / 32 GB / macOS 26.3，Temurin 25.0.5+8；下文的行数、字节数和停顿都是单次运行，未做统计。

先造一份有内容的日志。OldLoad 在 512 MB 堆下跑 12 秒：每轮分配 500 个 4 KB 数组和 500 个短命字符串，把一半数组放进 retained 直到 300 MB，让老年代占用越过 IHOP，从而触发并发标记与 Mixed GC：

java -Xms512m -Xmx512m \
  "-Xlog:gc*:file=logs/g1-full.log:time,uptime,level,tags" \
  -cp out OldLoad 12 300

这条命令产出的文件 25831 行、2666754 字节（约 2.5 MiB）。它的停顿类型覆盖 Young、Concurrent Start、Mixed、Remark、Cleanup，足够拆字段用。

统一日志：一条命令与五个装饰器

-Xlog 的语法是 -Xlog[:[selector][:[output][:[decorators][:output-options]]]]。生产上最常用的一条是：

java "-Xlog:gc*:file=/var/log/libraryd/gc-%p.log:time,uptime,level,tags:filecount=5,filesize=50M" \
  -jar libraryd.jar

逐段拆：

片段	含义	注意
`gc*`	所有以 `gc` 为前缀的标签集合	等价于 `gc` 加 `gc+heap`、`gc+phases` 等全部子标签
`file=...`	输出到文件	`%p` 展开为 PID，多实例不会互相覆盖
`time,uptime,level,tags`	装饰器：墙钟、启动后秒数、级别、标签	少了 `tags` 就不知道这行属于哪个子标签
`filecount=5`	保留 5 个轮转文件	不含当前活动文件
`filesize=50M`	单文件达到 50 MB 轮转	单位支持 K/M/G

time 是 2026-10-28T11:25:02.987+0800 这种带时区的墙钟，uptime 是 0.064s 这种相对启动的秒数。两者都要：墙钟用于和监控、请求日志对齐，uptime 用于排除「启动阶段特别慢」的干扰。

轮转行为可以直接验证。用 -Xms64m -Xmx64m 跑 2 秒，把阈值压到 200 KB：

java -Xms64m -Xmx64m \
  "-Xlog:gc*:file=logs/rotate.log:time,uptime,level,tags:filecount=2,filesize=200K" \
  -cp out GcLoad 2
ls -l logs/rotate.log*

本机 ls 输出是 100937 logs/rotate.log、204817 logs/rotate.log.0、204814 logs/rotate.log.1：活动文件加两个约 200 KB 的历史文件。

filecount=2 产生 rotate.log（活动文件）加 .0、.1 两个历史文件。本机三份文件的首行都在 mid-stream：.1 从 GC(422) Using 2 workers of 9 for evacuation 开始，.0 从 GC(562) Pause Young (Normal) 开始，活动文件从 GC(703) Old regions: 25->25 开始，没有一份包含启动时的 Using G1 行。这是排查时最容易踩的坑：轮转之后，「这个进程用的哪个收集器」只存在于最早的文件里，而它已经被删了。要保留启动信息，就给启动日志单独开一个不轮转的输出，或在启动脚本里显式记录收集器。

逐字段解析一行 GC 日志

取一条 Mixed GC：

[2026-10-28T11:25:03.170+0800][0.246s][info][gc,start    ] GC(9) Pause Young (Mixed) (G1 Evacuation Pause)
[2026-10-28T11:25:03.171+0800][0.247s][info][gc          ] GC(9) Pause Young (Mixed) (G1 Evacuation Pause) 431M->313M(512M) 0.964ms

第二行是汇总行，字段如下：

字段	值	含义
`GC(9)`	9	本次 GC 的序号，从 0 开始，进程内单调递增
`Pause Young (Mixed)`	—	停顿类型：Young 表示回收新生代，Mixed 表示同时回收部分老年代 region
`(G1 Evacuation Pause)`	—	触发原因：新生代疏散
`431M->313M`	—	回收前堆占用 431 MB，回收后 313 MB
`(512M)`	512 MB	当前堆总容量，不是 `-Xmx` 的必然值
`0.964ms`	0.964 ms	本次 STW 停顿的墙钟时长

一条日志回答不了「这 0.964 ms 花在哪」。要拆停顿内部，需要 gc+phases。下面是同一份日志里 GC(0) 的完整块（-Xlog:gc* 才有）：

[2026-10-28T11:25:02.987+0800][0.064s][info][gc,start    ] GC(0) Pause Young (Normal) (G1 Evacuation Pause)
[2026-10-28T11:25:02.988+0800][0.064s][info][gc,task     ] GC(0) Using 9 workers of 9 for evacuation
[2026-10-28T11:25:02.996+0800][0.072s][info][gc,phases   ] GC(0)   Pre Evacuate Collection Set: 0.14ms
[2026-10-28T11:25:02.996+0800][0.072s][info][gc,phases   ] GC(0)   Merge Heap Roots: 0.03ms
[2026-10-28T11:25:02.996+0800][0.072s][info][gc,phases   ] GC(0)   Evacuate Collection Set: 7.45ms
[2026-10-28T11:25:02.996+0800][0.072s][info][gc,phases   ] GC(0)   Post Evacuate Collection Set: 0.13ms
[2026-10-28T11:25:02.996+0800][0.072s][info][gc,phases   ] GC(0)   Other: 0.43ms
[2026-10-28T11:25:02.996+0800][0.072s][info][gc,heap     ] GC(0) Eden regions: 47->0(197)
[2026-10-28T11:25:02.996+0800][0.072s][info][gc,heap     ] GC(0) Survivor regions: 0->6(6)
[2026-10-28T11:25:02.996+0800][0.072s][info][gc,heap     ] GC(0) Old regions: 2->20
[2026-10-28T11:25:02.996+0800][0.072s][info][gc,heap     ] GC(0) Humongous regions: 0->0
[2026-10-28T11:25:02.996+0800][0.072s][info][gc,metaspace] GC(0) Metaspace: 205K(384K)->205K(384K) NonClass: 197K(256K)->197K(256K) Class: 7K(128K)->7K(128K)
[2026-10-28T11:25:02.996+0800][0.072s][info][gc          ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 48M->24M(512M) 8.486ms
[2026-10-28T11:25:02.996+0800][0.072s][info][gc,cpu      ] GC(0) User=0.01s Sys=0.04s Real=0.01s

这张块里最该看的是 Evacuate Collection Set: 7.45ms。它占了 8.486 ms 总停顿的 88%，说明时间花在「把存活对象复制到新 region」。Pre、Merge Heap Roots、Post、Other 加起来不到 1 ms，调这些阶段没有意义。

gc,heap 的四行给出对象流向：Eden 从 47 个 region 清空，Survivor 从 0 涨到 6，Old 从 2 涨到 20。这一轮有 18 个 region 的对象晋升到老年代，是 Mixed GC 的触发条件之一。

gc,cpu 的 User=0.01s Sys=0.04s Real=0.01s 说明 GC 线程的 CPU 时间远大于墙钟时间——这是并行回收的正常形状（9 个 worker 同时干活）。如果 Real 接近 0.5s 而 User 只有 0.05s，说明线程在等 I/O 或被操作系统调度挂起，不是 CPU 密集。

标签体系：四个子标签各回答什么

gc* 会打开所有子标签，但排查时通常只需要其中几个。按「能回答什么问题」分类：

标签	回答的问题	典型行
`gc`	有没有停顿、多长、回收了多少	`Pause Young (Mixed) ... 431M->313M(512M) 0.964ms`
`gc+heap`	各分代/region 的进出量	`Old regions: 2->20`
`gc+phases`	停顿内部各阶段耗时	`Evacuate Collection Set: 7.45ms`
`gc+ergo`	收集器为什么做这个决定	`Initiate concurrent cycle (concurrent cycle initiation requested)`
`gc+ref`	引用处理阶段做了什么	`Skipped PhantomRefsPhase of Reference Processing: no references`

gc+ergo=debug 能直接看到并发周期为什么启动：

[0.116s][debug][gc,ergo] GC(6) Initiate concurrent cycle (concurrent cycle initiation requested)
[0.118s][debug][gc,ergo] GC(7) Running G1 Root Region Scan using 2 workers for 15 work units.

GC(6) 这一行是 IHOP 触发并发标记的直接证据。没有它，只能从 Pause Young (Concurrent Start) 反推「大概是老年代占用到了阈值」。

gc+ref=debug 在引用处理时给出每个阶段的执行情况：

[0.075s][debug][gc,ref ] GC(0) ReferenceProcessor::execute queues: 1, RefProcThreadModel::Single, marks_oops_alive: false
[0.075s][debug][gc,ref ] GC(0) Skipped KeepAliveFinalRefsPhase of Reference Processing: no references
[0.075s][debug][gc,ref ] GC(0) Skipped PhantomRefsPhase of Reference Processing: no references
[0.089s][debug][gc,ref ] GC(2) Skipped SoftWeakFinalRefsPhase of Reference Processing: no references

queues: 1 表示有一个 ReferenceQueue 注册；no references 表示这一轮没有待处理的软/弱/虚引用。如果应用大量使用 WeakHashMap，这里会出现非零的处理量，且 Ref Proc 阶段会出现在 gc+phases 的耗时里——引用处理是停顿的一部分，不是免费的。

分配失败：Evacuation Failure 与 Full GC 死亡螺旋

分配失败是 GC 日志里最该警觉的信号。把堆压到 32 MB 再跑同一份负载：

java -Xms32m -Xmx32m "-Xlog:gc*:file=logs/g1-evac.log" -cp out GcLoad 5

本机输出摘录：

[1.044s][info][gc] GC(832) Pause Young (Mixed) (G1 Evacuation Pause) (Evacuation Failure: Allocation) 28M->20M(32M) 0.872ms
[1.100s][info][gc] GC(887) Pause Young (Mixed) (G1 Evacuation Pause) (Evacuation Failure: Allocation) 28M->19M(32M) 0.673ms
[1.114s][info][gc] GC(902) Pause Young (Mixed) (G1 Evacuation Pause) (Evacuation Failure: Allocation) 28M->21M(32M) 1.572ms

(Evacuation Failure: Allocation) 的意思是：疏散过程中找不到空闲 region 容纳存活对象，只能放弃这次疏散，把对象留在原 region。它不会让这次 Young GC 失败，但会让本该晋升的对象滞留在新生代，下一次 GC 的压力更大。

注意 JDK 25 的措辞。很多旧文档写的是 to-space exhausted，本机在 JDK 25 的 libjvm.dylib 里检索不到这个字符串：

strings "$JAVA_HOME/lib/server/libjvm.dylib" | grep -c "to-space exhausted"

本机输出：

JDK 25 用的是 (Evacuation Failure: <reason>) 格式，reason 为 Allocation 等。按旧字符串 grep 会漏掉全部失败事件。

这份日志的统计结果更说明问题：

collector      : G1
gc events      : 3432
total pause    : 3594.8 ms
avg pause      : 1.047 ms
p50 / p99      : 0.350 / 12.634 ms
max pause      : 23.853 ms
heap after last: 25 MB / 32 MB

pause type                                               count   total ms   max ms
Pause Full (G1 Compaction Pause)                           198     2402.1   23.853
Pause Young (Normal) (G1 Evacuation Pause)                2493      924.1    4.543
Pause Young (Normal) (G1 Evacuation Pause) (Evacuation Failure: Allocation)   316      107.9    2.708
Pause Young (Concurrent Start) (G1 Evacuation Pause)       244      107.2    2.374
Pause Young (Mixed) (G1 Evacuation Pause)                   37       21.5    0.956
Pause Young (Prepare Mixed) (G1 Evacuation Pause)           45       15.6    0.481
Pause Young (Mixed) (G1 Evacuation Pause) (Evacuation Failure: Allocation)     8        8.2    1.572
Pause Remark                                                46        7.3    0.263
Pause Cleanup                                               45        0.9    0.044

5 秒里出现 198 次 Full GC，总停顿 2402 ms，占墙钟的 48%。这就是死亡螺旋：疏散失败 → 老年代无法回收 → 触发 Full GC（G1 的 Full GC 是串行整理）→ 停顿变长 → 应用分配更慢 → 下一次仍然失败。

处理顺序不是调参数，而是先确认堆是否根本不够：28M->20M(32M) 说明存活对象稳定在 20 MB，32 MB 的堆只有 12 MB 余量，任何突发分配都会失败。把堆调到 128 MB 后，同一份负载的 Evacuation Failure 消失。参数只能缓解，不能修复「堆小于工作集」。

用脚本把日志变成指标

人工读几万行不现实。scripts/jvm/gc-summary.py 只做一件事：把 Pause 行抽出来，按类型聚合，给出 count、总时长、p50/p99、最大停顿：

#!/usr/bin/env python3
import re
import sys
from collections import defaultdict

PAUSE = re.compile(
    r"GC\((\d+)\)\s+(Pause .+?)\s+"
    r"(\d+)([KMG])->(\d+)([KMG])\((\d+)([KMG])\)\s+([\d.]+)ms"
)
USING = re.compile(r"\[info\s*\]\[gc\s*\]\s+Using (\S+)")
UNIT = {"K": 1 / 1024, "M": 1, "G": 1024}


def mb(value, unit):
    return int(value) * UNIT[unit]


def main(path):
    events, collector = [], "unknown"
    for line in open(path, encoding="utf-8", errors="replace"):
        if using := USING.search(line):
            collector = using.group(1)
        if match := PAUSE.search(line):
            gc_id, kind, before, bu, after, au, total, tu, ms = match.groups()
            events.append((int(gc_id), kind.strip(), mb(before, bu),
                           mb(after, au), mb(total, tu), float(ms)))
    if not events:
        print(f"{path}: no pause lines")
        return 1
    pauses = sorted(e[5] for e in events)
    total = sum(pauses)
    by_kind = defaultdict(list)
    for event in events:
        by_kind[event[1]].append(event[5])
    at = lambda p: pauses[min(len(pauses) - 1, int(round((len(pauses) - 1) * p)))]
    print(f"collector      : {collector}")
    print(f"gc events      : {len(events)}")
    print(f"total pause    : {total:.1f} ms")
    print(f"avg pause      : {total / len(events):.3f} ms")
    print(f"p50 / p99      : {at(0.5):.3f} / {at(0.99):.3f} ms")
    print(f"max pause      : {pauses[-1]:.3f} ms")
    print(f"heap after last: {events[-1][3]:.0f} MB / {events[-1][4]:.0f} MB")
    print()
    print(f"{'pause type':<56}{'count':>6}{'total ms':>11}{'max ms':>9}")
    for kind, values in sorted(by_kind.items(), key=lambda kv: -sum(kv[1])):
        print(f"{kind:<56}{len(values):>6}{sum(values):>11.1f}{max(values):>9.3f}")


if __name__ == "__main__":
    sys.exit(main(sys.argv[1]))

三个实现细节值得说明：

正则用非贪婪的 (Pause .+?) 匹配类型，因为 Pause Young (Normal) (G1 Evacuation Pause) 里有两层括号，贪婪匹配会跨过整个类型。
单位不假设是 MB。年轻代小时日志会输出 K，UNIT 负责换算；本机所有 G 单位在 4 GB 以下不会出现，但脚本仍然处理。
collector 从 [info][gc] Using ... 提取。轮转后这个文件里可能没有这行，输出会是 unknown，需要拼上最早的文件。

仓库里的 scripts/jvm/gc-summary.py 还会打印最慢的 3 次停顿，便于直接定位到 GC 序号；上面为了篇幅省略了这一段。

用本机 12 秒日志运行：

python3 scripts/jvm/gc-summary.py logs/g1-full.log

本机输出：

collector      : G1
gc events      : 1983
total pause    : 1418.0 ms
avg pause      : 0.715 ms
p50 / p99      : 0.780 / 2.641 ms
max pause      : 33.332 ms
heap after last: 390 MB / 512 MB

pause type                                               count   total ms   max ms
Pause Young (Normal) (G1 Evacuation Pause)                 780      814.3   33.332
Pause Young (Concurrent Start) (G1 Evacuation Pause)       394      379.7   11.302
Pause Remark                                               394      184.6    6.176
Pause Cleanup                                              393       19.6    0.266
Pause Young (Mixed) (G1 Evacuation Pause)                   11       10.4    1.107
Pause Young (Prepare Mixed) (G1 Evacuation Pause)           11        9.4    0.992

最大停顿 33.332 ms 出现在 GC(1)，那是启动后第一次 Young GC，堆从 221 MB 降到 121 MB，是最重的一次。稳态下的 Young GC 中位数是 0.780 ms。如果只报告「平均停顿 0.715 ms」，会掩盖启动阶段和偶发的 33 ms；如果只报告「最大 33 ms」，会高估稳态成本。两个都要给。

同样的脚本跑 Parallel 日志，形状立刻不同：1119 条停顿全部是 Pause Young (Allocation Failure)，p50 0.628 ms、p99 10.490 ms、最大 21.007 ms，总停顿 1435.5 ms。只有一种停顿类型，没有 Remark/Cleanup 这些并发阶段。p99 比中位数高一个数量级，说明停顿分布长尾明显——这是 Parallel 的典型特征，也是它不适合 P99 敏感服务的原因。

在 libraryd 里落地：日志落盘与轮转

libraryd 的 GC 日志不走应用日志框架，直接用 JVM 的 -Xlog 输出到独立文件。原因是 GC 日志量远大于业务日志，混在一起会淹没业务信息，也无法用 JVM 自带的轮转。

scripts/jvm/collect.sh 负责启动时拼参数：

LOG_DIR="${LIBRARYD_LOG_DIR:-/var/log/libraryd}"
PID_TAG="$(date +%Y%m%d-%H%M%S)"
mkdir -p "$LOG_DIR"
exec java -Xms2g -Xmx2g -XX:+UseG1GC -XX:MaxGCPauseMillis=100 \
  "-Xlog:gc*:file=${LOG_DIR}/gc-${PID_TAG}.log:time,uptime,level,tags:filecount=5,filesize=50M" \
  -cp libraryd-app/target/libraryd-app.jar com.plume.library.app.AppMain

三个决定：

文件名带启动时间戳，而不是只用 %p。容器重启后 PID 会复用，时间戳能区分不同代际的日志。
filecount=5,filesize=50M 最多占 300 MB（5 个历史文件加活动文件）。按本机这份日志 12 秒 2.6 MB（约 220 KB/s）的速率估算，50 MB 大约覆盖 4 分钟的高频日志；低峰期可能几小时才轮转一次，这个上限对磁盘是可接受的。
日志目录挂载到持久卷。容器被删除时 /var/log 会一起消失，事故复盘时没有日志可查。

采集脚本还要记录一份「启动快照」：jcmd "$PID" VM.info | grep -E "garbage-first|Using|Compilation|Memory" 加 jcmd "$PID" VM.flags 写进 ${LOG_DIR}/startup-${PID_TAG}.txt。这份文件只有几 KB，却能在日志轮转后回答「当时用的哪个收集器、堆多大、开了哪些参数」。

排障时的读取顺序：

gc-summary.py 看总停顿、p99、最大停顿，确认 GC 是否量级上能解释延迟；
找最大停顿对应的 GC 序号，回到原始日志看它的完整块（gc+phases 的哪个阶段）；
如果出现 Evacuation Failure 或 Pause Full，先查堆容量与存活集，而不是调参数。

常见错误与边界

错误一：zsh 里不给 -Xlog 加引号。 -Xlog:gc*:file=gc.log 中的 * 会被 zsh 当通配符展开，报 no matches found: -Xlog:gc*:file=gc.log。所有 -Xlog 参数都要写成 "-Xlog:gc*:file=gc.log"。

错误二：只开 -Xlog:gc 就想看停顿细节。 -Xlog:gc 只有汇总行，没有 gc+phases、gc+heap、gc+ergo、gc+ref。要定位「停顿花在哪」，必须用 gc* 或显式加上子标签。反过来，gc* 的日志量可能是 gc 的 10 倍以上（本机 12 秒 25831 行），生产上要评估磁盘。

错误三：按旧文档 grep to-space exhausted。 JDK 25 的输出是 (Evacuation Failure: Allocation)，libjvm 里没有 to-space exhausted 字符串。用旧关键字写的告警规则会永远不触发。

错误四：把 0.005s 当成 ZGC 的停顿。 ZGC 在 -Xlog:gc 下输出的是整个并发周期的时长（如 Major Collection (Warmup) ... 0.005s），停顿在 gc,phases 里。把周期时长当停顿，会得到「ZGC 停顿 5 ms」的错误结论。

边界一：日志里的容量不是 -Xmx。 (512M) 是当时的堆容量，G1 会按需扩展；heap after last 也只是最后一条日志时刻的占用，不是峰值。峰值要看 jcmd GC.heap_info 或监控采样。

边界二：p99 的分位数口径。 脚本用的是「排序后取第 99% 位置的样本」，不是插值。样本少时（比如只有 20 条停顿），p99 就等于最大值，容易被单次异常带偏。样本少于 100 条时，直接看最大值和完整分布更可靠。

边界三：GC 日志不能解释所有延迟。 本机 12 秒日志的总停顿是 1418 ms，占墙钟约 12%。如果接口 P99 是 800 ms 而最大 GC 停顿只有 33 ms，GC 不是原因，应该转去看线程栈、锁竞争或下游调用。

小结

统一日志的一条命令是 "-Xlog:gc*:file=...:time,uptime,level,tags:filecount=5,filesize=50M"，zsh 下必须加引号。
一行 GC(9) Pause Young (Mixed) (G1 Evacuation Pause) 431M->313M(512M) 0.964ms 包含序号、停顿类型、触发原因、回收前后占用、堆容量和停顿六项信息。
gc+phases 拆停顿内部：本机 GC(0) 的 8.486 ms 里有 7.45 ms 花在 Evacuate Collection Set。
gc+ergo 给出并发周期启动原因，gc+ref 给出引用处理阶段；引用处理是停顿的一部分。
JDK 25 的分配失败标记是 (Evacuation Failure: Allocation)，libjvm 中已无 to-space exhausted 字符串；本机 32 MB 堆下 5 秒出现 198 次 Full GC。
gc-summary.py 把 1983 条停顿聚合成 p50 0.780 ms、p99 2.641 ms、最大 33.332 ms；Parallel 同负载 p99 10.490 ms，只有一种停顿类型。
libraryd 的 GC 日志独立落盘、带时间戳、轮转上限 300 MB，并额外保存 VM.info/VM.flags 启动快照。

知道了一次 GC 里发生了什么，下一个问题是「G1 的这些数字怎么调」。6.2 从 region 大小开始，把 Humongous、IHOP 和 Mixed GC 逐个拆开。

阅读导航：上一节：5.3 收集器谱系：Serial、Parallel、G1、ZGC 与 Shenandoah · 下一节：6.2 G1 调优：Region、Humongous 与 Mixed GC 。

继续阅读

探索更多技术文章

浏览归档，发现更多关于系统设计、工具链和工程实践的内容。

全部文章返回首页