Java虚拟机之GC日志

阅读GC日志是解决JVM问题的基础

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

“33.125：”和“100.667：”代表了GC发生的时间,这个数字的含义是从Java虚拟机启动以来经过的秒数GC日志开头的“[GC”和“[FullGC”说明了这次垃圾收集的停顿类型而不是用来区分新生代GC还是老年代GC的。如果有“Full”,说明这次GC是发生了Stop-The-World的,例如下面这段新生代收集器ParNew的日志也会出现“[FullGC”(这一般是因为出现了分配担保失败之类的问题,所以才导致STW)。如果是调用System.gc()方法所触发的收集,那么在这里将显示“[FullGC(System)”。

[FullGC283.736：[ParNew：261599K-＞261599K（261952K），0.0000288secs]

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

“3324K-＞152K(3712K)”含义是“GC前该内存区域已使用容量-＞GC后该内存区域已使用容量(该内存区域总容量)”。而在方括号之外的“3324K-＞152K(11904K)”表示“GC前Java堆已使用容量-＞GC后Java堆已使用容量(Java堆总容量)”。

“0.0025925secs”表示该内存区域GC所占用的时间,单位是秒。有的收集器会给出更具体的时间数据,如“[Times：user=0.01sys=0.00,real=0.02secs]”,这里面的user、sys和real与Linux的time命令所输出的时间含义一致,分别代表用户态消耗的CPU时间、内核态消耗的CPU事件和操作从开始到结束所经过的墙钟时间(WallClockTime)。CPU时间与墙钟时间的区别是,墙钟时间包括各种非运算的等待耗时,例如等待磁盘I/O、等待线程阻塞,而CPU时间不包括这些耗时,但当系统有多CPU或者多核的话,多线程操作会叠加这些CPU时间,所以读者看到user或sys时间超过real时间是完全正常的。