Java虚拟机-理解GC日志

向右看齐 2021-11-26 10:50 324阅读 0赞

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

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：`代表了GC发生的时间，这个数字的含义是从Java虚拟机启动以来经过的秒数。

GC日志开头的`[GC`和`[Full GC`说明了这次垃圾收集的停顿类型，而不是用来区分新生代GC还是老年代GC的。如果有`Full`，说明这次GC是发生了Stop-The-World的，例如下面这段新生代收集器RarNew的日志也会出现`[Full GC`（这一般是因为出现了分配担保失败之类的问题，所以才导致STW）。如果是调用System.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 New Generation`。如果采用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时间是完全正确的。