GC 日志与调优：先写下目标，再从日志里找证据，最后才动一个参数

所以看 GC 有两个层次：一次停多久（日志直接写着），以及停顿占了多少时间（要自己加起来算）。后者一旦接近 100%，系统就处理不过来了，单次停顿再短也没用。

缺的是这几样：一个可以判对错的目标，一份同样流量下的基线日志，从日志里算出来的几个数，以及一次只改一处。有了它们，调优就是一个能验证的实验，而不是凭感觉。

本页选 GC 日志，配一个 80 行的统计程序：日志的格式简单，每次停顿都有记录，开着的开销很小，出了事故之后也还在。不管用哪个工具，都按下面这五步走。

1一行日志怎么读

GC(100) Eden regions: 20->0(20)        # Eden 用了 20 块，全部清空；下一轮还给 20 块
GC(100) Survivor regions: 1->1(3)
GC(100) Old regions: 188->188        # 老年代 188 块，这次 Young GC 不碰它
GC(100) Humongous regions: 18->18   # 缓存那张大哈希表的数组
GC(100)   Evacuate Collection Set: 1.53ms  # 复制活对象，停顿的大头

2三样数：分别对应三个目标

这三样数为什么能下结论，靠的是复制式回收的两条规律。它们能从 G1 页讲的“复制活对象”直接推出来：

据此可以分出两类问题。回收后的占用低、但 GC 很频繁或停顿长，是参数问题，可以靠堆大小、新生代大小或收集器解决。回收后的占用接近上限、而且一直在涨，是代码问题：东西还被引用着，怎么调参数都回收不掉。

3为什么这样设计：三个目标不能同时最好，收集器只能各选一个优先

G1 为什么只要一个停顿目标：它不把新生代的大小写死，每次 GC 之后，按“上次复制了多少活对象、花了多久”预测下一次，再决定 Eden 给几块 region。被放弃的做法是 CMS、Parallel 那一代的思路：新生代和老年代按比例切死，大小由人用 -Xmn、NewRatio、SurvivorRatio 来定。流量一变，原来调好的比例就不对了。同样是 256 MB 的堆、206 MB 的活对象，两种做法实测的分法：

这里 Parallel 输掉，不是因为它“慢”，而是它的固定比例和这个场景的活对象对不上。⑤ 里把堆加到 768 MB，老年代变成 512 MB，Parallel 的 GC 时间占比反而是全场最低的 0.7%。但那样就超出了 256 MB 的内存预算。所以哪个收集器更好，要看目标是什么。

# 1. 日志（JDK 9+）：%p = pid，%t = 启动时间；默认就会轮转（5 个文件 × 20 MB），这里改大一点
-Xlog:gc*:file=gc-%p-%t.log:time,uptime,level,tags:filecount=10,filesize=50m

# 2. 目标（先只动这三个）
-Xms256m -Xmx256m            # 内存预算；两者相等，堆不用伸缩
-XX:MaxGCPauseMillis=200     # G1 的停顿目标，默认 200
-XX:GCTimeRatio=12           # GC 时间占比目标 = 1/(1+N)；G1 默认 12，Parallel 默认 99

# 3. 现场看一眼
jstat -gcutil <pid> 1000     # O 列（老年代 %）是不是只涨不跌
jcmd <pid> VM.flags          # JVM 实际用的参数
jcmd <pid> GC.heap_info

JDK 8 的写法（-XX:+PrintGCDetails -Xloggc: 等）、-Xmn 为什么别写、停顿目标设多小合适，都放到第⑥步。

1写下目标

2代码和命令

// 最近订单缓存：LRU，满了踢最老的
static final Map<Long, Order> RECENT = new LinkedHashMap<>(…, true) {
  protected boolean removeEldestEntry(Map.Entry<Long, Order> e) {
    return size() > CACHE; }                // -DcacheK=1600
};
static long handle(long id, ThreadLocalRandom r) {
  String body = "{\"userId\":" + … + "}";  // 解析报文：临时对象
  …
  RECENT.put(id, new Order(…));            // 订单：活得久
  byte[] resp = new byte[TEMP_KB * 1024];  // 响应：48 KB 临时对象
  if (LEAK) LEAKED.add(new byte[4096]);    // -Dleak=true：只放不删
  …
}
// main：先把缓存装满，空闲 1 秒，再按 -Drate 匀速发请求
long plan = start + n * interval;          // 计划到达时刻
if (plan > now) LockSupport.parkNanos(plan - now);
handle(n, r);
lat[n] = System.nanoTime() - plan;         // 排队也算进延迟

cd study-labs/java
JAVA_HOME=/usr/lib/jvm/java-17-openjdk-arm64 \
  mvn -q -pl jvm/jvm-gc-log-tuning compile
cd jvm/jvm-gc-log-tuning
J=/usr/lib/jvm/java-17-openjdk-arm64/bin/java
M=labs.jvm.jvm_gc_log_tuning

# 基线：G1 默认，大促流量
$J -XX:+UseG1GC -Xms256m -Xmx256m \
   -Xlog:gc*:file=g1.log \
   -Drate=4000 -DcacheK=1600 \
   -cp target/classes $M.OrderService

# 统计：目标 50 ms、5%，从压测开始的那一秒算
$J -cp target/classes $M.GcLogStats g1.log 50 5 1.4

3基线：G1 默认参数

$ java -XX:+UseG1GC -Xms256m -Xmx256m … OrderService
缓存预热 1600000 个订单，用了 311 ms；堆上限 256 MB
压测从 JVM 启动后第 1.4 秒开始（GcLogStats 的第 4 个参数填它，跳过预热）
处理 120000 个请求，用了 30.0 秒（计划 30 秒），实际 4000 个/秒
延迟：p50 0.06 ms，p99 1.54 ms，p99.9 3.35 ms，最长 8.3 ms
$ java … GcLogStats g1.log 50 5 1.4
统计 1.4～31.5 秒，停顿 417 次，合计 589 ms
  Pause Young (Concurrent Start)     54 次
  Pause Young (Normal)               225 次
  Pause Remark                       54 次
  Pause Cleanup                      54 次
  Pause Young (Prepare Mixed)        15 次
  Pause Young (Mixed)                15 次
GC 时间占比 2.0%（目标 ≤ 5%）
停顿：p50 1.6 ms，p99 3.5 ms，最长 7.9 ms（目标 ≤ 50 ms）
分配速率约 196 MB/s
GC 后堆占用：最低 206 MB，前一半平均 210 MB，后一半平均 210 MB，最后 207 MB，堆上限 256 MB
结论：达标：别动参数

三样数都达标，回收后的占用也平稳，按五步法的规则到这里就该停手。日志里还有一个值得记下的信号：30 秒内做了 54 轮并发标记，平均半秒多一轮。原因是活对象占了堆的 80%，余量只有 50 MB，G1 一直在忙着回收老年代，这部分开销占的是 CPU，不算在停顿里。活对象再涨一点，就该加堆或给缓存瘦身了。

4有人“优化”了一下：换成吞吐量收集器 Parallel

$ java -XX:+UseParallelGC -Xms256m -Xmx256m … OrderService
处理 120000 个请求，用了 36.6 秒（计划 30 秒），实际 3279 个/秒
延迟：p50 3300.05 ms，p99 6516.55 ms，p99.9 6619.65 ms，最长 6649.0 ms
$ java … GcLogStats parallel.log 50 5 1.7
统计 1.7～38.4 秒，停顿 172 次，合计 36086 ms
  Pause Full                         172 次
GC 时间占比 98.4%（目标 ≤ 5%）
停顿：p50 204.4 ms，p99 301.0 ms，最长 308.6 ms（目标 ≤ 50 ms）
GC 后堆占用：最低 201 MB，前一半平均 201 MB，后一半平均 201 MB，最后 201 MB，堆上限 245 MB
结论：有 Full GC，但回收后降下来了：堆相对活对象太小，或晋升太快，先看堆是不是活对象的 3 倍以上

判断：回收后稳定在 201 MB，没有上涨，所以不是泄漏，而是参数问题。原因在 ④-3 那张图里：Parallel 的老年代固定是 171 MB，比活对象还小。处理办法只能二选一：换回 G1，或者给 Parallel 加内存。两种都跑了一遍：

5只改一处，和基线比

实测 本机 2 核 ARM，JDK 17.0.20.1，每行各跑一次。“停顿”只统计压测期间，预热时的停顿已经跳过。在这个场景里，满足全部三个目标的只有 G1。如果预算允许 768 MB，而且更看重吞吐，Parallel 就是更好的选择。所以哪个更好，取决于第 1 步写下的目标。

6再来一次：这回是代码有泄漏

日常流量（每秒 2000 单，缓存 90 万个订单），打开 -Dleak=true：每个请求往一个只放不删的 static 列表里塞 4 KB。分别用 256 MB 和 512 MB 的堆跑。

两条线的形状一模一样，只是 512 MB 那条更晚碰到上限。日志里对应的就是全景第 8 站说的那种行：Pause Full (G1 Compaction Pause) 253M->243M(256M) 82.802ms，整理完一遍几乎没变。这时候该做的是第 9 站的事：堆转储、直方图，找出是谁一直攥着这些对象。

版本差异

GC 日志体检台先猜，再体检

算法和 GcLogStats.java 基本一样，已在 node 里用三段样本核对过：统计时长从第一次停顿开始算到最后一行（日志的时间戳记在停顿结束的时刻）；分配量是“这次回收前”减去“上次回收后”的累加；结论按“Full GC 后仍占堆 90% 以上的次数是否过半 → 回收后占用是否一路上涨 → 有没有 Full GC → 是否超出目标”的顺序判断。

刻意练习：由易到难

下一圈

• JFR 录一段：用 jdk.ObjectAllocationSample 找到每秒分配 196 MB 的是哪几行代码，减少分配，而不是去调 GC
• G1 的停顿预测模型：G1Policy 怎么根据前几次的复制速度决定下一轮 Eden 用几块
• 安全点日志 -Xlog:safepoint：停顿里有多少是在等所有线程到齐
• 容器里的 JVM（地图上 J03 的第 8 个知识点）：MaxRAMPercentage 和堆外内存怎么一起算
• JVM 故障排查（第 9 站）：堆转储、MAT 里的 GC Root 路径，把 ⑤ 第 6 步的泄漏查到具体的那一行

自测