GC日志详解[乐乐独记]

1、静态分析GC日志

启动一个Web程序
在程序中加上对应的参数生成GC日志在文件中
-Xloggc:./gc-%t.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCCause
-XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=100M

参数	含义
-Xloggc:./gc-%t.log	表示生成的日志文件放在哪里，./表示当前路径
-Xloggc:D:/gc-%t.log	表示生成的日志文件放在哪里，D:/表示D盘
%t	代表时间
-XX:+PrintGCDetails	打印GC详细信息
-XX:+PrintGCDateStamps	打印GC发生日期戳
-XX:+PrintGCTimeStamps	打印GC发生时间戳
-XX:+PrintGCCause	打印GC原因
-XX:+UseGCLogFileRotation	滚动记录日志
-XX:NumberOfGCLogFiles=10	将GC日志陆续分到10个文件
-XX:GCLogFileSize=100M	每个文件的大小为100M

分析GC日志时，有一个规律
num1->num2(num3)
num1：代表gc之前某空间的使用容量
num2：代表gc之后某空间的使用容量
num3：代表整个空间的总容量

1.1、Parallel GC日志

由上图可看到，程序启动之后，先打印了一些JVM参数，再做了一些GC操作，我从上图截图一个minor gc和一个full gc来做分析，详情如下：
minor gc如下图所示:

// 上图中的数据
2020-07-10T17:45:40.296+0800: 1.285:
[GC (Allocation Failure) 
[PSYoungGen: 49152K->3892K(57344K)] 
49152K->3900K(188416K), 
0.0080059 secs] 
[Times: user=0.03 sys=0.00, real=0.01 secs] 

参数	含义
GC (Allocation Failure)	minor gc（分配空间失败）
PSYoungGen	年轻代
49152K->3892K(57344K)	49152K表示年轻代gc前已使用容量 3892K表示年轻代gc后已使用容量 57344K表示年轻代当前总容量
49152K->3900K(188416K)	49152K表示整个堆gc前已使用容量 3900K表示整个堆gc后已使用容量 188416K表示整个堆当前总容量
0.0080059 secs	表示这次gc执行的时间

full gc如下图所示:

2020-07-10T17:45:44.450+0800: 5.439: 
[Full GC (Metadata GC Threshold) 
[PSYoungGen: 4286K->0K(201216K)]
[ParOldGen: 3289K->7277K(74752K)] 
7575K->7277K(275968K), 
[Metaspace: 20854K->20854K(1069056K)],
0.0542303 secs] 
[Times: user=0.11 sys=0.00, real=0.06 secs] 

参数	含义
Full GC (Metadata GC Threshold)	full gc（分配元空间失败）
PSYoungGen	年轻代
4286K->0K(201216K)	4286K表示年轻代gc前已使用容量 0K表示年轻代gc后已使用容量 201216K表示年轻代当前总容量
ParOldGen	老年代
3289K->7277K(74752K)	3289K表示老年代gc前已使用容量 7277K表示老年代gc后已使用容量 74752K表示老年代当前总容量
7575K->7277K(275968K)	7575K表示整个堆gc前已使用容量 7277K表示整个堆gc后已使用容量 275968K表示整个堆当前总容量
Metaspace	元空间
20854K->20854K(1069056K)	20854K表示元空间gc前已用容量 20854K表示元空间gc后已用容量 1069056K表示元空间当前总容量
0.0542303 secs	表示这次gc执行的时间

1.2、CMS GC日志

public class GCLog {
    byte[] bytes = new byte[1024*100];   // 1kb = 1024字节

    public static void main(String[] args) throws InterruptedException {
        ArrayList<GCLog> heapTests = new ArrayList<>();
        while (true) {
            heapTests.add(new GCLog());
            Thread.sleep(10);
        }
    }
}

使用上面这个代码，设置下面这些参数
-Xloggc:d:/gc-cms-%t.log -Xms10M -Xmx10M
-XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M
-XX:+PrintGCDetails -XX:+PrintGCDateStamps
-XX:+PrintGCTimeStamps -XX:+PrintGCCause
-XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10
-XX:GCLogFileSize=100M -XX:+UseParNewGC
-XX:+UseConcMarkSweepGC
打印出的GC日志如下图所示

重复的东西我就不说了，这里重点说一下红框中的内容，就可以看出是我们CMS中的几个过程：

日志	中文过程
CMS-concurrent-mark-start	初始标记
CMS-concurrent-mark	并发标记
CMS-concurrent-preclean-start	预清理准备
CMS-concurrent-preclean	预清理
CMS Final Remark	重新标记
CMS-concurrent-sweep-start	并发清理准备
CMS-concurrent-sweep	并发清理
CMS-concurrent-reset-start	并发重置准备
CMS-concurrent-reset	并发重置

注意：在CMS并发失败时，会用Serial Old垃圾收集器去执行Full gc，如下图红框中所示，就是在OOM之前产生的一次单线程垃圾收集

1.3、G1 GC日志

使用CMS里面的代码。
设置如下参数：
-Xloggc:d:/gc-g1-%t.log -Xms10M -Xmx10M
-XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M
-XX:+PrintGCDetails -XX:+PrintGCDateStamps
-XX:+PrintGCTimeStamps -XX:+PrintGCCause
-XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10
-XX:GCLogFileSize=100M -XX:+UseG1GC
然后生成的日志如下图所示：

看红框中的东西，就是大概一些G1垃圾收集的过程

日志	中文过程
concurrent-root-region-scan-start	根扫描开始
concurrent-root-region-scan-end	根扫描结束
concurrent-mark-start	并发标记开始
concurrent-mark-end	并发标记结束
remark	最终标记
cleanup	筛选回收

注意：同样的，当mixed gc无法进行时，也会触发单线程垃圾收集器，如下图所示：

2、使用工具分析GC日志

这里我们可以使用一些工具去分析GC日志，就不用我们肉眼去看了。
这里我推荐一个网站GCeasy(部分功能收费)，当我们打开网站之后，导入我们的GC日志，点击分析按钮，下面是我分析之后截取的几张图：

1. GC持续时间范围比例

2. GC之后堆使用情况

3. 各种GC时间的统计

10、辅助知识

10.1、元空间不足也会导致full gc

从上面这张图我们可以看出，有两次full gc，而且这两次full gc的原因都是由于元空间内存不足触发的，所以，在项目上线时我们需要对元空间的初始大小调大一些，如果不设置，默认为21M。
-XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M