老废物乐园

菜单

Administrator
发布于 2018-07-05 / 1615 阅读
35

GC 日志怎么读？从一行日志看懂一次 Young GC

#GC#日志

师傅甩给我一段 GC 日志，我一个字都看不懂

上个月排查一个接口抖动的问题，师傅在机器上敲了一串命令，屏幕上刷出这么一段东西：

2018-07-05T14:23:11.482+0800: 6.291: [GC (Allocation Failure) [PSYoungGen: 524288K->43520K(611840K)] 699072K->218304K(2015232K), 0.0318470 secs] [Times: user=0.11 sys=0.02, real=0.03 secs]

他问我："看出什么问题了吗？"我看了半天，只认识 GC 两个字母。

那天晚上我把 GC 日志的每个字段都查了一遍，顺便搞清楚了年轻代回收到底在干什么。写下来给同样懵的同学。

先把日志打开

JDK 8 里推荐这几个参数：

-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintGCTimeStamps
-Xloggc:/data/logs/gc.log
-XX:+UseGCLogFileRotation
-XX:NumberOfGCLogFiles=5
-XX:GCLogFileSize=20M

逐个说一下：

  • PrintGCDetails：打印详细日志，不带这个只有一行简单的 [GC 1024K->512K]，信息量太少。
  • PrintGCDateStamps：加上墙钟时间（2018-07-05T14:23:11.482+0800）。不加的话只有相对 JVM 启动的秒数，和业务日志对不上时间点。
  • UseGCLogFileRotation 那三个：日志滚动。不加的话 gc.log 会一直涨，我们线上曾经有个服务跑了半年，gc.log 长到 8GB，把磁盘写满了。

另外强烈建议加上 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/dump，OOM 时自动留快照。

要注意：JVM 重启时如果不带 -XX:+UseGCLogFileRotation，新的 gc.log 会直接覆盖旧的，事故现场就没了。我们后来统一在启动脚本里用 gc-%t.log 这种带时间戳的文件名。

逐段拆解一行 Young GC

还是拿开头那行：

2018-07-05T14:23:11.482+0800: 6.291: [GC (Allocation Failure) [PSYoungGen: 524288K->43520K(611840K)] 699072K->218304K(2015232K), 0.0318470 secs] [Times: user=0.11 sys=0.02, real=0.03 secs]
片段含义
2018-07-05T14:23:11.482+0800GC 发生的墙钟时间
6.291JVM 启动到第 6.291 秒时发生
GC这次是 Young GC（Minor GC）。写 Full GC 才是全堆回收
(Allocation Failure)触发原因：年轻代分配内存失败
PSYoungGen年轻代使用的收集器，PS = Parallel Scavenge（JDK 8 服务端默认）
524288K->43520K(611840K)年轻代：回收前 512MB → 回收后 42.5MB，年轻代总容量 598MB
699072K->218304K(2015232K)整个堆：回收前 682.5MB → 回收后 213MB，堆总容量 1922MB
0.0318470 secs本次 GC 耗时 31.8 毫秒
user=0.11 sys=0.02 real=0.03CPU 时间：用户态 0.11s、内核态 0.02s、实际墙钟 0.03s

几个容易看错的地方

第一，两组数字的单位和含义不一样。 中括号里的是年轻代自己的变化，外面的是整个堆的变化。我一开始以为外面那组是老年代，不是，是整个堆。想看老年代得用差值估算：699072 - 524288 = 174784K（回收前老年代占用），218304 - 43520 = 174784K（回收后老年代占用）。两次算出来一样，说明这次 GC 老年代占用没变，没有对象晋升到老年代。

如果算出来老年代变大了，比如从 174784K 涨到 190000K，说明有 15MB 的对象从年轻代晋升到了老年代。

第二，user 远大于 real 是正常的。 上面 user=0.11 而 real=0.03，是因为 Parallel Scavenge 是多线程并行收集，8 个 GC 线程各跑了 0.011 秒，加起来就是 0.11 秒。判断一次 GC 对业务的影响，只看 real，real 才是 STW（Stop The World）暂停的时间。

反过来，如果 user + sys 明显小于 real，那说明 GC 线程在等 CPU、等 IO，或者机器负载太高抢不到时间片，这种情况要查机器本身。

第三，PSYoungGen 里的 PS。 不同收集器前缀不一样：

  • PSYoungGen / ParOldGen：Parallel 收集器（吞吐量优先，JDK 8 默认）
  • ParNew / CMS：ParNew + CMS 组合，需要 -XX:+UseConcMarkSweepGC
  • DefNew：Serial 收集器，单线程，一般只在客户端模式或者单核机器上见到

看懂年轻代在干什么

光看懂数字不够，还得知道这 31.8 毫秒里发生了什么。年轻代用的是复制算法，内存分成三块：

+---------+---------+-----------+
|  Eden   |  From   |    To     |
|  (8/10) |  (1/10) |   (1/10)  |
+---------+---------+-----------+
       \______ 年轻代 ______/

一次 Young GC 的过程：

  1. 新对象都在 Eden 区分配；
  2. Eden 满了触发 GC，把 Eden 和 From 区里还活着的对象复制到 To 区；
  3. 清空 Eden 和 From 区；
  4. 交换 From 和 To 的角色（下次 GC 时，现在的 To 变成 From）。

所以 524288K->43520K 里的 43520K 就是"活下来的对象被复制到了 To 区"。存活对象越少，复制成本越低，GC 越快——这也就是为什么大部分对象"朝生夕死"是好事，也是为什么 Young GC 通常比 Full GC 快一个数量级。

为什么必须有 From 和 To 两个区？如果只有一个 Survivor 区，Eden 里存活的对象复制过去之后，下一次 GC 时 Survivor 里的对象也可能要被回收，但它和 Eden 来的对象混在一起，没法整理出连续空间（会产生内存碎片）。两个区来回倒，每次倒的时候把存活对象紧凑排列，就顺便解决了碎片问题。

上面那次 GC，年轻代回收后剩 42.5MB，占 To 区（611840/10 ≈ 59MB）的 72%。如果存活对象超过 To 区的容量，就会发生过早晋升——放不下的对象被直接塞进老年代，这会加速老年代填满、触发 Full GC。

再看一行 Full GC

2018-07-05T14:35:02.117+0800: 717.926: [Full GC (Ergonomics) [PSYoungGen: 43520K->0K(611840K)] [ParOldGen: 1397760K->823456K(1403392K)] 1441280K->823456K(2015232K), [Metaspace: 89567K->89321K(1140736K)], 2.8456721 secs] [Times: user=9.82 sys=0.31, real=2.85 secs]

这行的信息量大得多：

  • 耗时 2.85 秒，是 Young GC 的 90 倍。这 2.85 秒里应用是完全暂停的，接口全部卡死。这就是为什么 Full GC 频繁是严重问题。
  • (Ergonomics) 是触发原因，意思是 JVM 的自适应策略判断"该做一次 Full GC 了"。常见的原因还有 System.gc()（有人代码里调了）、Metadata GC Threshold（元空间不够）。
  • ParOldGen: 1397760K->823456K 是老年代从 1365MB 降到 804MB，回收了 561MB。
  • Metaspace 那一段是元空间（JDK 8 用元空间替代了永久代），注意元空间在本地内存里，不在堆里，所以它不计入堆的那几个数字。
  • user=9.82 real=2.85，多线程并行，但 2.85 秒的暂停依然太长。

怎么看一份完整的日志

我现在的习惯是先抓三个宏观指标。

1. Young GC 的频率和耗时

grep '\[GC ' gc.log | wc -l              # Young GC 次数
grep -o 'real=[0-9.]*' gc.log | sort -rn | head -5   # 最慢的几次

健康的标准：Young GC 间隔在几十秒以上，单次耗时 10~50ms。如果几秒一次，说明年轻代太小或者对象创建太快。

2. Full GC 的频率

grep 'Full GC' gc.log | wc -l

几次事故时的数字：正常服务一天 2~3 次；出问题那天是 一小时内 47 次。一般一天超过 10 次就该查了。

3. 晋升量

grep -o 'PSYoungGen: [0-9]*K->[0-9]*K' gc.log

如果每次 GC 后年轻代剩余量（箭头右边的数）都很大，而且老年代持续上涨，说明有大量对象活过了 GC，需要调整 -XX:MaxTenuringThreshold（晋升年龄阈值，默认 15）或者直接加大年轻代。

我最后对那次抖动做了什么

回到开头那个问题。我把那台机器一整天的日志统计了一遍：Young GC 平均 8 秒一次，单次耗时 20~40ms；Full GC 一天 31 次，平均 2.1 秒。接口抖动的时刻和几次 Full GC 的时间点完全对得上。

根因是我们有个定时任务每小时全量加载 200 万条数据到内存做计算，产生的临时对象把老年代撑爆了。师傅给的修改是加大堆、调整年轻代比例：

-Xms4g -Xmx4g
-XX:NewRatio=2        # 年轻代:老年代 = 1:2
-XX:SurvivorRatio=8   # Eden:Survivor = 8:1

改完之后 24 小时的数据：Young GC 从 8 秒一次变成 26 秒一次，Full GC 从 31 次降到 3 次，接口 P99 从 2.3 秒降到 180ms。

不过说实话，加大堆只是缓解。真正治本的是把那个定时任务改成流式处理，别一次性把 200 万条全读进内存——那是另一个故事了。

参考

事务隔离级别与脏读、不可重复读、幻读
缓存穿透、击穿、雪崩：一次缓存雪崩...