每一种收集器的日志形式都是由他们自身的实现所决定，换而言之，每个收集器的日志格式都可以不一样。但虚拟机设计者为了方便用户阅读，将各个收集器的日志都维持一定的共性，例如以下两段经典的GC日志：
33.125[GC[DefNew3324K-152K3712K0.0025925 secs]3324K-152K11904K0.0031680 secs]
1 0 0.6 6 7[F u l l G C[T e n u r e d0 K-2 1 0 K1 0 2 4 0 K0.0 1 4 9 1 4 2 s e c s]4603K-210K19456K[Perm2999K-2999K21248K]0.0150007 secs][Timesuser=0.01 sys=0.00real=0.02 secs]
最前面的数字“33.125：”和“100.6667”代表了GC发生的时间，这个数字的含义是从Java虚拟机启动以来经过的秒数。
GC日志开头的“[GC”和“[Full GC”说明了这次垃圾收集的停顿类型，而不是用来区分新生代GC还是老年代GC的。如果有“Full”，说明这次GC是发生了Stop the world的例如下面的这段新生代收集器ParNew的日志也会出现“[Full GC”（这一般出现了分配担保失败之类的问题，所以才导致STW）。如果是调用System.gc()方法所触发的手机，那么在这里将显示“Full GC(System)”。
[Full GC 283.736[ParNew261599K-261599K261952K0.0000288 secs]
接下来的“[DefNew”、“[Tenured”、“[Perm”表示GC发生的区域，这里显示的区域名称与使用的GC收集器是密切相关的，例如上面样例所使用的Serial收集器中的新生代名称为“Default New Generation”，所以显示的是“[DefNew”。如果是ParNew收集器，新生代名称就会变为“[ParNew”，意为“Parallel New Generation”。如果采用Parallel Scavenge收集器，那它配套的新生代成为“PSYongGen”，老年代和永久代同理，名称也是由收集器决定的。
后面括号内部的“3324->152k（3712）”含义是“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事件和操作从开始到结束所经过的墙钟时间。CPU时间与墙钟时间的区别是，墙钟时间包括各种非运算的等待耗时，例如等待磁盘I/O、等待线程阻塞，而CPU时间不包括这些耗时，但当系统有多CPU或者多核的话，多线程操作会叠加这些CPU时间，所以读者看到user或sys时间超过real时间是完全正常的。
网友评论