理解GC日志

发表于 更新于 分类于
阅读GC日志是处理Java虚拟机内存问题的基础技能，他只是一些人为规定的规则，没有太多技术含量。这里只是对两段典型的GC日志分析。

每一种收集器的日志形式都是由它们自身的实现所决定的,换而言之,每个收集器的日志格式都可以不一样。但虚拟机设计者为了方便用户阅读,将各个收集器的日志都维持一定的共性,例如以下两段典型的GC日志:

1
2
3
33.125: [GC [DefNew: 3324K->152K(3712K), 0.0025925 secs] 3324K->152K(11904K), 0.0031680secs]

100.667: [Full GC [Tenured: 0K->210K(10240K), 0.0149142 secs] 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”：代表了GC发生的时间，这个数字的含义是从Java虚拟机启动以来经过的秒数。

GC日志开头的“[GC”和“[Full GC”说明了这次垃圾收集的停顿类型，而不是用来区分新生代GC还是老年代GC的。如果有“Full”，说明这次GC是发生了Stop-The-World的。

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

后面方括号内部的“3324K->152K(3712K)” 含义是 “GC前该区域已使用容量 -> GC后该区域已使用容量（该内存区域总容量）”。

而在方括号之外的“3324K->152K(11904K)” 表示 “GC前Java堆已使用容量 -> GC后Java堆已使用容量（Java堆总容量）”。

再往后，“0.0031680secs”表示该内存区域GC所占用的时间，单位是秒。有的收集器会给出更具体的时间数据，如“[Times: user=0.01 sys=0.00, real=0.02 secs]”，这里面的user、sys和real与Linux的time命令所输出的含义一致，分别代表用户态消耗的CPU时间、内核态消耗的CPU时间和操作从开始到结束所经过的墙钟时间。

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