每一种垃圾收集器的日志形式都是由它们自身的实现所决定的,换而言之,每个收集器的日志格式都可以不一样。但虚拟机设计者为了方便用户阅读,将各个收集器的日志都维持一定的共性,例如以下两段典型的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时间是完全正确的。