JVM gc日志分析

一、常用gc日志配置参数

-XX:+PrintGC #输出GC日志
-XX:+PrintGCDetails #输出GC的详细日志
-XX:+PrintGCTimeStamps #输出GC的时间戳（代表了GC发生的时间，这个数字的含义是从Java
虚拟机启动以来经过的秒数）
-XX:+PrintGCDateStamps #输出GC的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）
-XX:+PrintHeapAtGC #在进行GC的前后打印出堆的信息
-XX:+PrintTenuringDistribution  #输出显示在survivor空间里面有效的对象的岁数情况
-XX:+UseGCLogFileRotation  #使用日志文件旋转
-XX:NumberOfGCLogFiles=12  #日志文件数量
-XX:GCLogFileSize=128M  #日志文件大小

-Xloggc:../logs/gc.log  #日志文件的输出路径

二、gc日志含义分析

配置

-XX:+PrintGCDetails -XX:+PrintGCDateStamps  -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=12 -XX:GCLogFileSize=128M -Xloggc:logs/gc-flume.log

日志

2018-04-28T11:04:12.391+0800: 64.264: [GC [PSYoungGen: 85440K->3488K(89600K)] 147397K->69117K(164352K), 0.0052610 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
2018-04-28T11:04:14.774+0800: 66.647: [GC [PSYoungGen: 85408K->3604K(105984K)] 151037K->72914K(180736K), 0.0040650 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2018-04-28T11:04:14.778+0800: 66.651: [Full GC [PSYoungGen: 3604K->0K(105984K)] [ParOldGen: 69309K->28865K(77312K)] 72914K->28865K(183296K) [PSPermGen: 12750K->12750K(27648K)], 0.0468910 secs] [Times: user=0.11 sys=0.00, real=0.04 secs] 

第三条Full gc为例

1.GC日志开头的“[GC”和“[Full GC”说明了这次垃圾收集的停顿类型，如果有“Full”，说明这次GC是发生了Stop-The-World，如下几种情况下会发生full gc：

1.System.gc()方法的调用，可通过DisableExplicitGC来禁止
2.老年代空间不足
3.永生区空间不足
4.CMS GC时出现promotion failed和concurrent mode failure
5.统计得到的Minor GC晋升到旧生代的平均大小大于老年代的剩余空间
6.堆中分配很大的对象
6.存在rmi调用时，默认会每分钟执行一次System.gc，可以通过-Dsun.rmi.dgc.server.gcInterval=3600000来设置大点的间隔。

详见：https://blog.csdn.net/chenleixing/article/details/46706039

2.PSYoungGen表示GC发生的区域，PSYoungGen表示新生代采用Parallel Scavenge收集器。使用Serial收集器新生代名称为DefNew，使用ParNew收集器名称为ParNew

3.后面方括号内部含义是“GC前该内存区域已使用容量-＞GC后该内存区域已使用容量（该内存区域总容量）”。PSYoungGen: 3604K->0K(105984K)代表新生代内存回收情况，[ParOldGen: 69309K->28865K(77312K)代表老年代内存回收情况，而在方括号之外的“172914K->28865K(183296K)”表示“GC前Java堆已使用容量-＞GC后Java堆已使用容量（Java堆总容量）”，[PSPermGen: 12750K->12750K(27648K)]代表永久代内存回收情况。

4.再往后，“0.0052610 secs”表示该内存区域GC所占用的时间，单位是秒

5.[Times: user=0.01 sys=0.00, real=0.00 secs] ；这里面的user、sys和real与Linux的time命令所输出的时间含义一致，分别代表用户态消耗的CPU时间、 内核态消耗的CPU事件和操作从开始到结束所经过的墙钟时间（Wall Clock Time）。 CPU时间与墙钟时间的区别是，墙钟时间包括各种非运算的等待耗时，例如等待磁盘I/O、 等待线程阻塞，而CPU时间不包括这些耗时，但当系统有多CPU或者多核的话，多线程操作会叠加这些CPU时间，所以读者看到user或sys时间超过real时间是完全正常的。

我们再对数据做一个简单的分析

从第二次GC记录中我们可以看到 Young GC回收了 85408K->3604K=81804K的内存
Heap区通过这次回收总共减少了 151037K->72914K=78123K的内存。
81804K-78123K=3681K说明通过该次Young GC有3681K的内存被移动到了Old Gen

我们来验证一下
在第一次Young GC 的Old Gen的大小为69117-3488=65629K
第二次Young GC 的Old Gen的大小72914-3604=69310K
Old Gen在第二次Young GC以后内存增加了69310-65629=3681K 与预计的相符