阅读GC日志是处理Java虚拟机内存问题的基础技能。
以下两端典型的GC日志：
33.125：[GC [DefNew：3324K->152K(3712K),0.0025925 secs] 3324K->152K(11904K),0.0031680 secs]
100.667:[Full GC [Tenured：OK->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的，例如下面这段新生代收集器ParNew的日志也会出现“[Full GC”（这一般是因为出现了分配担保失败之类的问题，所以才导致STW）。如果是调用System.gc()方法所触发的收集，那么在这里将显示“[Full GC(System)”。
[Full GC 283.736: [PaetNew: 261599K->261599K(261952K),0.000288 secs]
接下来的“[DefNew”、“[Tenured”、"[Perm"表示GC发生的区域，这里显示的区域名称与使用的GC收集器是密切相关的。
后面方括号内部的“3324K->152K(3712K)”含义是“GC前该内存区域已使用容量->GC后该内存区域已使用容量（该内存区域总容量）”。而在方括号之外的“3324K->152K（11904K）”表示“GC前Java堆已使用容量（Java堆总容量）”。
再往后，“0.0025925 secs”表示该内存区域GC所占用的时间，单位是秒。有的收集器会给出更具体的时间数据，如“[Times:user=0.01 sys=0.00,real=0.02 secs]”,这三个参数分别代表用户态消耗的CPU时间、内核态消耗的CPU事件和操作从开始到结束所经过的墙钟时间。CPU时间与墙钟时间的区别是，后者包括各种非运算的等待耗时，例如等待磁盘I/O、等待线程阻塞，而前者不包括这些耗时，但当系统有多CPU或者多核的话，多线程操作会叠加这些CPU时间，所以读者看到user或sys时间超过real时间是完全正常的。
网友评论