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日志,点击分析按钮,下面是我分析之后截取的几张图:
- GC持续时间范围比例
- GC之后堆使用情况
- 各种GC时间的统计
10、辅助知识
10.1、元空间不足也会导致full gc
从上面这张图我们可以看出,有两次full gc,而且这两次full gc的原因都是由于元空间内存不足触发的,所以,在项目上线时我们需要对元空间的初始大小调大一些,如果不设置,默认为21M。
-XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M