【JVM】GC日志解读实例

水深无声 2022-01-29 03:04 404阅读 0赞

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

2019-05-20T12:26:59.890+0800: 348146.272: [GC (Allocation Failure)  4197972K->2706428K(10781376K), 0.0913078 secs]
    2019-05-20T12:28:52.287+0800: 348258.669: [GC (Allocation Failure)  4274108K->2778565K(10781376K), 0.0918657 secs]
    2019-05-20T12:30:12.585+0800: 348338.967: [GC (Allocation Failure)  4346245K->2867129K(10781376K), 0.0968981 secs]
    2019-05-20T12:30:31.290+0800: 348357.673: [GC (Allocation Failure)  4434809K->2978105K(10781376K), 0.1424276 secs]

JVM的GC日志的主要参数包括如下几个：

-XX:+PrintGC 输出GC日志 
    -XX:+PrintGCDetails 输出GC的详细日志 
    -XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式） 
    -XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800） 
    -XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息 
    -XX:+PrintGCApplicationStoppedTime // 输出GC造成应用暂停的时间 
    -Xloggc:../logs/gc.log 日志文件的输出路径

Allocation Failure：  
表明本次引起GC的原因是因为在年轻代中没有足够的空间能够存储新的数据了。  
“\[GC”和“\[Full GC”说明了这次垃圾收集的停顿类型，而不是用来区分新  
生代GC还是老年代GC的。如果有“Full”，说明这次GC是发生了Stop-The-World的。  
GC参数选择打印详细信息，观察下面一条日志：

2019-05-20T12:43:09.707+0800: 31.748: [GC (Allocation Failure) 2019-05-20T12:43:09.707+0800: 31.748: [ParNew: 1608648K->97265K(1763584K), 0.0314101 secs] 1608648K->97265K(10781376K), 0.0316494 secs] [Times: user=0.49 sys=0.09, real=0.04 secs]

“\[ParNew”、“\[Tenured”、“\[Perm”表示GC发生的区域，如果是ParNew收集器，新生代名称就为“\[ParNew”，意为“Parallel New Generation”。如果采用Parallel Scavenge收集器，那它配套的新生代称为“PSYoungGen”，老年代和永久代同理，名称也是由收集器决定的。  
后面方括号内部的“1608648KK-＞97265K（1763584K）”含义是“GC前该内存区域已使用容量-＞GC后该内存区域已使用容量（该内存区域总容量）”。而在方括号之外的“1608648K-＞97265K（10781376K）”表示“GC前Java堆已使用容量-＞GC后Java堆已使用容量（Java堆总容量）”。  
再往后，“0.0316494 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时间是完全正常的。