JVM性能调优——GC日志

阅读 GC 日志是处理 JVM 内存问题的基础技能，它只是一些人为确定的规则，每一种收集器的日志形式都是由它们自身的实现所决定的，但 JVM 设计者为了方便用户阅读，将各个收集器的日志都维持了一定的共性。

例如下面两段典型的日志：

33.125: [GC [DefNew: 3324K->152K (3712K), 0.0025925secs] 3324K->152K (11904K), 0.0031680 secs]
100.667: [FullGC [Tenured: 0K->210K (10240K), 0.0149142secs] 4603K->210K (19456K), [Perm: 2999K->2999K (21248K)], 0.0150007 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]

数字 “33.125” 和 “100.667” 表示从 JVM 启动以来经过的秒数。

“[GC” 和 “[Full GC” 说明了这次垃圾收集的停顿类型，而不是用来区分新生代 GC 还是老年代 GC 的。如果有 “Full”，说明这次 GC 是发生了 “Stop The World” 的，例如下面这段新生代收集器 ParNew 的日志也会出现 “[Full GC” (一般是因为出现了分配担保失败之类的问题，导致 STW)。如果是调用 System.gc() 方法所触发的 GC，那么在这里将显示 “[Full GC (System)”。

[Full GC 283.736: [ParNew: 261599K->261599K (261952K)，0.0000288 secs]

“[DefNew”、"[Tenured"、"[Perm" 表示GC发生的区域，这里显示的区域名称与使用的 GC 收集器是密切相关的，例如上面样例所使用的 Serial 收集器中的新生代名为 “Default New Generation”，所以显示的是 “[DefNew”。
如果是 ParNew 收集器，新生代名称就会变为 “[ParNew”。
如果是 Parallel Scavenge 收集器，新生代名称就会变为 “PSYoungGen”，老年代和永久代同理，名称也是由收集器决定的。

后面方括号内部的 “3324K->152K (3712K)” 即 “GC 前该内存区域已使用容量->GC 后该内存区域已使用容量 (该内存区域总容量)”。
而在方括号之外的 “3324K->152K (11904K)” 即 “GC 前 Java 堆已使用容量->GC 后 Java 堆已使用容量 (Java堆总容量)”。

再往后，“0.0025925 secs” 表示该内存区域 GC 所占用的时间，单位是秒。

有的收集器会给出更具体的时间数据，如 “[Times: user=0.01 sys=0.00，real=0.02 secs]”，这里面的 user、sys 和 real 与 Linux 的 time 命令所输出的时间含义一致，分别代表用户态消耗的CPU时间、内核态消耗的CPU事件和操作从开始到结束所经过的墙钟时间 (Wall Clock Time)。

CPU 时间与墙钟时间的区别是，墙钟时间包括各种非运算的等待耗时，例如等待磁盘 I/O、等待线程阻塞，而 CPU 时间不包括这些耗时，但当系统有多 CPU 或者多核的话，多线程操作会叠加这些 CPU 时间，所以读者看到 user 或 sys 时间超过 real 时间是完全正常的。