读懂 GC 日志

目标

用一个小型 Java 程序生成真实的 GC 日志并读懂它——停顿次数、停顿时间、堆大小的影响、收集器对比、jstat、jcmd。

为什么重要

接到“服务很慢”的反馈时，第一个分岔路口就是：是不是 GC。GC 日志中没有长时间的停顿，凶手就在别处（锁、连接池耗尽）。开启日志的方法和读日志的方法，以及堆大小和收集器如何影响停顿，都通过真实的数字来观察。材料 Churn.java 以 java Churn <초> <유지MB> [반복당KB]（占位符依次为秒数、保留的 MB 数、每次迭代的 KB 数）的方式运行，会一直持有“保留的 MB 数”那么多的对象，其余部分则不断丢弃。

步骤

1. 用 mkdir -p /root/jvm/gc && cd /root/jvm/gc && javac -d . /opt/lab/fixtures/jvm/Churn.java 编译。会生成 /root/jvm/gc/Churn.class，并且 java -cp /root/jvm/gc Churn 1 0 会打印出 done。
2. 用 java -Xmx256m -Xlog:gc:file=/root/jvm/gc/gc.log -cp /root/jvm/gc Churn 5 24 生成 GC 日志。日志中必须有以 Using 开头的收集器行和 Pause Young 行。
3. 用 -Xlog:gc*:file=/root/jvm/gc/gc-detail.log 生成详细日志（相同负载，5 秒、24MB）。统计包含 Pause Young 且以 ms 结尾的行（停顿完成行）的数量，以 young_pauses=<n> 一行写入 /root/jvm/gc/answer.txt。
4. 用 -Xms64m -Xmx64m 运行相同负载，生成 /root/jvm/gc/gc-64.log（-Xlog:gc*），再用 -Xmx256m 运行，生成 /root/jvm/gc/gc-256.log，然后在 /root/jvm/gc/compare.txt 中写入 xmx64_pauses=<n> 和 xmx256_pauses=<n> 两行（统计方法与第 3 步相同）。64M 一侧必须更多。
5. 在 gc-256.log 中找到最长的停顿（Pause 行末尾的 ms 值），以 max_pause_ms=<x> 写入 /root/jvm/gc/pause.txt（精确到小数点后第三位，保持日志中的原值）。
6. 在后台启动 java -Xmx128m -cp /root/jvm/gc Churn 12 24，并用 jstat -gc <pid> 1000 5 > /root/jvm/gc/jstat.txt 留下以 1 秒为间隔的 5 次输出。必须有表头（S0C、EC、YGC、FGC……）和 5 行数据。
7. 分别用 -XX:+UseSerialGC -Xlog:gc:file=/root/jvm/gc/gc-serial.log 和 -XX:+UseG1GC -Xlog:gc:file=/root/jvm/gc/gc-g1.log 运行相同负载（-Xmx128m，5 秒、24MB），并把各自的最大停顿以 serial_max_pause_ms=<x> 和 g1_max_pause_ms=<x> 两行写入 /root/jvm/gc/collector.txt。
8. 让 Churn 再次在后台运行，同时用 jcmd <pid> GC.heap_info > /root/jvm/gc/heap_info.txt 和 jcmd <pid> VM.flags > /root/jvm/gc/vm_flags.txt 留下输出。heap_info 中必须有 total 和 used，vm_flags 中必须有 -XX:MaxHeapSize=。

参考

• 提取最大停顿：awk '/Pause/ && match($0,/[0-9.]+ms$/){v=substr($0,RSTART,RLENGTH-2)+0; if(v>m)m=v} END{print m}' gc-256.log
• 后台进程的 pid：先 java ... & PID=$!，再 jstat -gc $PID 1000 5。程序会自行结束。
• 常见错误：在 -Xlog:gc* 中统计 Pause Young 时，开始行和完成行都会被抓到——只统计以 ms 结尾的行。

编译材料

在 /root/jvm/gc 中编译 Churn.java，生成 Churn.class。java -cp /root/jvm/gc Churn 1 0 会打印 done。

格式是 javac -d <输出目录> <源文件>。这个类没有包，所以 -cp 中只需给出目录。

开启 GC 日志

用 -Xmx256m -Xlog:gc:file=/root/jvm/gc/gc.log 运行 Churn 5 24。日志中必须有 Using 行和 Pause Young 行。

-Xlog:gc:file=<路径> 会把 GC 事件输出到文件。第一行会告诉你使用的是哪种收集器。

在详细日志中统计停顿

用 -Xlog:gc*:file=/root/jvm/gc/gc-detail.log 运行相同的负载，统计包含 Pause Young 且以 ms 结尾的行数，以 young_pauses= 的形式写入 /root/jvm/gc/answer.txt。

gc* 会把一次停顿记录成 [gc,start] 和 [gc] 两行。只想统计完成行，就选以 ms 结尾的行：grep -E 'Pause Young.*ms$' | wc -l

堆越小，停顿越频繁

用 -Xms64m -Xmx64m 生成 gc-64.log，用 -Xmx256m 生成 gc-256.log（两者都用 -Xlog:gc*），并在 compare.txt 中写入 xmx64_pauses= 和 xmx256_pauses=。64M 一侧必须更多。

把相同的分配量放进较小的堆，Eden 区很快就满，Young GC 会变得频繁。统计方法与第 3 步相同。

看最大停顿，而不是平均值

在 gc-256.log 中，找出 Pause 行末尾 ms 值的最大值，以 max_pause_ms= 的形式写入 /root/jvm/gc/pause.txt。

参考部分的那一行 awk 就能提取最大值。值保持日志中小数点后第三位的原样。

用 jstat 观察运行中的进程

在后台启动 Churn 12 24 (-Xmx128m)，并用 jstat -gc 1000 5 > /root/jvm/gc/jstat.txt 留下输出。必须有表头和 5 行数据。

用 java ... & PID=$! 取得 pid，然后执行 jstat -gc $PID 1000 5。程序会在 12 秒后自行结束，所以要在这段时间内打印 5 次。

在相同负载下比较 Serial 和 G1

用 -XX:+UseSerialGC 生成 gc-serial.log，用 -XX:+UseG1GC 生成 gc-g1.log（-Xmx128m、-Xlog:gc、Churn 5 24），并在 collector.txt 中写入 serial_max_pause_ms= 和 g1_max_pause_ms=。

每个日志的第一行必须是 Using Serial / Using G1。最大停顿沿用第 5 步的 awk，只需换成对应的文件。

用 jcmd 获取堆信息和实际生效的标志

让 Churn 在后台运行的同时，用 jcmd GC.heap_info > /root/jvm/gc/heap_info.txt 和 jcmd VM.flags > /root/jvm/gc/vm_flags.txt 留下输出。

可以用 jcmd -l 确认 pid。VM.flags 会显示 JVM 实际应用的值（-XX:MaxHeapSize=…）——真相在这里，而不是在配置文件里。