GC日志分析(学习笔记)
查看GC的常用参数
参数 | 含义 | 备注 |
---|---|---|
-XX:+PrintGC | 输出GC日志 | 类似-verbose:gc ,JDK9中被替换为-Xlog:gc |
-XX:+PrintGCDetails | 输出GC详细日志 | JDK9中被替换为-Xlog:gc* |
-XX:+PrintGCTimeStamps | 输出GC的时间戳 | 以基准时间的形式,JDK9中为-Xlog:gc(*)::uptime (默认打开) |
-XX:+PrintGCDateStamps | 输出GC的时间戳 | 以日期的形式,如2021-03-08T17:21:30.123+0800,JDK9中为-Xlog:gc(*)::time ,且会顶掉默认的uptime格式 |
-XX:+PrintHeapAtGC | 在进行GC的前后打印出堆的信息 | JDK9中已经无法使用 |
-Xloggc:logs/gc.log | 日志文件的输出路径 | JDK9中为-Xlog:gc(*):logs/gc.log |
具体举例
代码如下:
public class GCLogTest {
public static void main(String[] args) {
ArrayList<byte[]> list = new ArrayList<>();
for (int i = 0; i < 500; i++) {
byte[] arr = new byte[1024 * 100];//100KB
list.add(arr);
}
}
}
- -Xms60m -Xmx60m -XX:+PrintGC
[0.004s][warning][gc] -XX:+PrintGC is deprecated. Will use -Xlog:gc instead.
[0.019s][info ][gc] Using G1
[0.040s][info ][gc] Periodic GC disabled
[0.113s][info ][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 21M->21M(60M) 7.335ms
[0.118s][info ][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 31M->31M(60M) 4.010ms
[0.120s][info ][gc] GC(2) Pause Young (Concurrent Start) (G1 Evacuation Pause) 37M->37M(60M) 2.310ms
[0.120s][info ][gc] GC(3) Concurrent Cycle
[0.122s][info ][gc] GC(4) Pause Young (Normal) (G1 Evacuation Pause) 42M->41M(60M) 0.903ms
[0.123s][info ][gc] GC(3) Pause Remark 51M->51M(60M) 0.212ms
[0.124s][info ][gc] GC(3) Pause Cleanup 51M->51M(60M) 0.025ms
[0.124s][info ][gc] GC(3) Concurrent Cycle 3.766ms
打印出了GC信息,但是注意第一行的warning。
- -Xms60m -Xmx60m -Xlog:gc
[0.023s][info][gc] Using G1
[0.047s][info][gc] Periodic GC disabled
[0.124s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 21M->21M(60M) 7.888ms
[0.129s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 31M->31M(60M) 4.369ms
[0.132s][info][gc] GC(2) Pause Young (Concurrent Start) (G1 Evacuation Pause) 37M->37M(60M) 2.116ms
[0.132s][info][gc] GC(3) Concurrent Cycle
[0.133s][info][gc] GC(4) Pause Young (Normal) (G1 Evacuation Pause) 42M->41M(60M) 0.827ms
[0.135s][info][gc] GC(3) Pause Remark 51M->51M(60M) 0.227ms
[0.136s][info][gc] GC(3) Pause Cleanup 51M->51M(60M) 0.029ms
[0.136s][info][gc] GC(3) Concurrent Cycle 4.357ms
可以看到,打印出了简易的GC信息,前面带有标准时间、日志等级和日志内容所属标签,没有打印堆信息。
- -Xms60m -Xmx60m -Xlog:gc*
[0.017s][info][gc,heap] Heap region size: 1M
[0.018s][info][gc ] Using G1
[0.018s][info][gc,heap,coops] Heap address: 0x00000000fc400000, size: 60 MB, Compressed Oops mode: 32-bit
[0.038s][info][gc ] Periodic GC disabled
[0.106s][info][gc,start ] GC(0) Pause Young (Normal) (G1 Evacuation Pause)
[0.106s][info][gc,task ] GC(0) Using 2 workers of 6 for evacuation
[0.113s][info][gc,phases ] GC(0) Pre Evacuate Collection Set: 0.0ms
[0.113s][info][gc,phases ] GC(0) Evacuate Collection Set: 7.1ms
[0.113s][info][gc,phases ] GC(0) Post Evacuate Collection Set: 0.1ms
[0.113s][info][gc,phases ] GC(0) Other: 0.3ms
[0.113s][info][gc,heap ] GC(0) Eden regions: 22->0(10)
[0.113s][info][gc,heap ] GC(0) Survivor regions: 0->3(3)
[0.113s][info][gc,heap ] GC(0) Old regions: 0->19
[0.113s][info][gc,heap ] GC(0) Archive regions: 0->0
[0.113s][info][gc,heap ] GC(0) Humongous regions: 0->0
[0.113s][info][gc,metaspace ] GC(0) Metaspace: 839K->839K(1056768K)
[0.113s][info][gc ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 21M->21M(60M) 7.509ms
[0.113s][info][gc,cpu ] GC(0) User=0.02s Sys=0.02s Real=0.01s
[0.114s][info][gc,start ] GC(1) Pause Young (Normal) (G1 Evacuation Pause)
[0.114s][info][gc,task ] GC(1) Using 2 workers of 6 for evacuation
[0.118s][info][gc,phases ] GC(1) Pre Evacuate Collection Set: 0.0ms
[0.118s][info][gc,phases ] GC(1) Evacuate Collection Set: 4.0ms
[0.118s][info][gc,phases ] GC(1) Post Evacuate Collection Set: 0.1ms
[0.118s][info][gc,phases ] GC(1) Other: 0.1ms
[0.118s][info][gc,heap ] GC(1) Eden regions: 10->0(6)
[0.118s][info][gc,heap ] GC(1) Survivor regions: 3->2(2)
[0.118s][info][gc,heap ] GC(1) Old regions: 19->30
[0.118s][info][gc,heap ] GC(1) Archive regions: 0->0
[0.118s][info][gc,heap ] GC(1) Humongous regions: 0->0
[0.118s][info][gc,metaspace ] GC(1) Metaspace: 840K->840K(1056768K)
[0.118s][info][gc ] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 31M->31M(60M) 4.248ms
[0.118s][info][gc,cpu ] GC(1) User=0.00s Sys=0.00s Real=0.00s
[0.119s][info][gc,start ] GC(2) Pause Young (Concurrent Start) (G1 Evacuation Pause)
[0.119s][info][gc,task ] GC(2) Using 2 workers of 6 for evacuation
[0.121s][info][gc,phases ] GC(2) Pre Evacuate Collection Set: 0.0ms
[0.121s][info][gc,phases ] GC(2) Evacuate Collection Set: 2.1ms
[0.121s][info][gc,phases ] GC(2) Post Evacuate Collection Set: 0.1ms
[0.121s][info][gc,phases ] GC(2) Other: 0.1ms
[0.121s][info][gc,heap ] GC(2) Eden regions: 6->0(5)
[0.121s][info][gc,heap ] GC(2) Survivor regions: 2->1(1)
[0.121s][info][gc,heap ] GC(2) Old regions: 30->37
[0.121s][info][gc,heap ] GC(2) Archive regions: 0->0
[0.121s][info][gc,heap ] GC(2) Humongous regions: 0->0
[0.121s][info][gc,metaspace ] GC(2) Metaspace: 840K->840K(1056768K)
[0.121s][info][gc ] GC(2) Pause Young (Concurrent Start) (G1 Evacuation Pause) 37M->37M(60M) 2.386ms
[0.121s][info][gc,cpu ] GC(2) User=0.00s Sys=0.00s Real=0.00s
[0.121s][info][gc ] GC(3) Concurrent Cycle
[0.121s][info][gc,marking ] GC(3) Concurrent Clear Claimed Marks
[0.121s][info][gc,marking ] GC(3) Concurrent Clear Claimed Marks 0.006ms
[0.121s][info][gc,marking ] GC(3) Concurrent Scan Root Regions
[0.121s][info][gc,marking ] GC(3) Concurrent Scan Root Regions 0.311ms
[0.121s][info][gc,marking ] GC(3) Concurrent Mark (0.121s)
[0.121s][info][gc,start ] GC(4) Pause Young (Normal) (G1 Evacuation Pause)
[0.121s][info][gc,marking ] GC(3) Concurrent Mark From Roots
[0.122s][info][gc,task ] GC(4) Using 2 workers of 6 for evacuation
[0.122s][info][gc,task ] GC(3) Using 2 workers of 2 for marking
[0.122s][info][gc,phases ] GC(4) Pre Evacuate Collection Set: 0.1ms
[0.122s][info][gc,phases ] GC(4) Evacuate Collection Set: 0.6ms
[0.122s][info][gc,phases ] GC(4) Post Evacuate Collection Set: 0.1ms
[0.122s][info][gc,phases ] GC(4) Other: 0.1ms
[0.122s][info][gc,heap ] GC(4) Eden regions: 5->0(10)
[0.122s][info][gc,heap ] GC(4) Survivor regions: 1->1(1)
[0.122s][info][gc,heap ] GC(4) Old regions: 37->41
[0.122s][info][gc,heap ] GC(4) Archive regions: 0->0
[0.122s][info][gc,heap ] GC(4) Humongous regions: 0->0
[0.122s][info][gc,metaspace ] GC(4) Metaspace: 840K->840K(1056768K)
[0.122s][info][gc ] GC(4) Pause Young (Normal) (G1 Evacuation Pause) 42M->41M(60M) 0.837ms
[0.122s][info][gc,cpu ] GC(4) User=0.00s Sys=0.00s Real=0.00s
[0.124s][info][gc,marking ] GC(3) Concurrent Mark From Roots 2.191ms
[0.124s][info][gc,marking ] GC(3) Concurrent Preclean
[0.124s][info][gc,marking ] GC(3) Concurrent Preclean 0.090ms
[0.124s][info][gc,marking ] GC(3) Concurrent Mark (0.121s, 0.124s) 2.312ms
[0.124s][info][gc,start ] GC(3) Pause Remark
[0.124s][info][gc,stringtable] GC(3) Cleaned string table, strings: 2940 processed, 3 removed
[0.124s][info][gc ] GC(3) Pause Remark 51M->51M(60M) 0.232ms
[0.124s][info][gc,cpu ] GC(3) User=0.00s Sys=0.00s Real=0.00s
[0.124s][info][gc,marking ] GC(3) Concurrent Rebuild Remembered Sets
[0.125s][info][gc,marking ] GC(3) Concurrent Rebuild Remembered Sets 0.479ms
[0.125s][info][gc,start ] GC(3) Pause Cleanup
[0.125s][info][gc ] GC(3) Pause Cleanup 51M->51M(60M) 0.039ms
[0.125s][info][gc,cpu ] GC(3) User=0.00s Sys=0.00s Real=0.00s
[0.125s][info][gc,marking ] GC(3) Concurrent Cleanup for Next Mark
[0.125s][info][gc,marking ] GC(3) Concurrent Cleanup for Next Mark 0.421ms
[0.125s][info][gc ] GC(3) Concurrent Cycle 4.023ms
[0.125s][info][gc,heap,exit ] Heap
[0.125s][info][gc,heap,exit ] garbage-first heap total 61440K, used 51176K [0x00000000fc400000, 0x0000000100000000)
[0.125s][info][gc,heap,exit ] region size 1024K, 11 young (11264K), 1 survivors (1024K)
[0.125s][info][gc,heap,exit ] Metaspace used 842K, capacity 4531K, committed 4864K, reserved 1056768K
[0.125s][info][gc,heap,exit ] class space used 80K, capacity 402K, committed 512K, reserved 1048576K
打印出了详细的GC信息,前面带有标准时间,以及堆的信息。
- -Xms60m -Xmx60m -Xlog:gc::time
[2021-03-08T20:27:20.666+0800] Using G1
[2021-03-08T20:27:20.688+0800] Periodic GC disabled
[2021-03-08T20:27:20.763+0800] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 21M->21M(60M) 7.475ms
[2021-03-08T20:27:20.768+0800] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 31M->31M(60M) 4.189ms
[2021-03-08T20:27:20.771+0800] GC(2) Pause Young (Concurrent Start) (G1 Evacuation Pause) 37M->37M(60M) 2.271ms
[2021-03-08T20:27:20.771+0800] GC(3) Concurrent Cycle
[2021-03-08T20:27:20.772+0800] GC(4) Pause Young (Normal) (G1 Evacuation Pause) 42M->41M(60M) 0.746ms
[2021-03-08T20:27:20.773+0800] GC(3) Pause Remark 51M->51M(60M) 0.211ms
[2021-03-08T20:27:20.773+0800] GC(3) Pause Cleanup 51M->51M(60M) 0.026ms
[2021-03-08T20:27:20.774+0800] GC(3) Concurrent Cycle 3.635ms
打印出了详简易的GC信息,前面带有真实时间,没有打印标准时间、日志等级和日志内容所属标签。
- -Xms60m -Xmx60m -Xlog:gc:logs/gc.log
日志信息会输出到logs/gc.log文件中。
JDK9中JVM日志系统的更新
JVM在JDK9中采用了统一的日志系统,GC日志也归入其中,因此原有的查看GC信息的方法都被弃用或删除。
具体可以查看官方文档:
相关中文资料可以参考:
- Java 9 揭秘(19. 平台和JVM日志) 中的第二节
日志文件分析
通过GC日志可以知道使用的回收器
- “[GC"和”[Full GC"说明了这次垃圾收集的停顿类型,如果有"Full"则说明GC发生了"Stop The World"
- 使用Serial收集器在新生代的名字是Default New Generation,因此显示的是"[DefNew"
- 使用ParNew收集器在新生代的名字会变成"[ParNew",意思是"Parallel New Generation"
- 使用Parallel scavenge收集器在新生代的名字是”[PSYoungGen"
- 老年代的收集和新生代道理一样,名字也是收集器决定的
- 使用G1收集器的话,会显示为"garbage-first heap"
PSYongGen中具体数据的含义
-
Allocation Failure表明本次引起GC的原因是因为在年轻代中没有足够的空间能够存储新的数据了。
[ PSYoungGen: 5986K->696K(8704K) ] 5986K->704K (9216K)
-
中括号内:GC回收前年轻代大小,回收后大小,(年轻代总大小)
-
括号外:GC回收前年轻代和老年代大小,回收后大小,(年轻代和老年代总大小)
-
user代表用户态回收耗时,sys内核态回收耗时,real实际耗时。由于多核线程切换的原因,时间总和可能会超过real时间
Young GC分析:
Full GC分析:
堆空间日志分析
示例代码如下:
public class GCLogTest1 {
private static final int _1MB = 1024 * 1024;
public static void testAllocation() {
byte[] allocation1, allocation2, allocation3, allocation4;
allocation1 = new byte[2 * _1MB];
allocation2 = new byte[2 * _1MB];
allocation3 = new byte[2 * _1MB];
allocation4 = new byte[4 * _1MB];
}
public static void main(String[] agrs) {
testAllocation();
}
}
参数设置如下:
-Xms20M -Xmx20M -Xmn10M -Xlog:gc* -XX:SurvivorRatio=8 -XX:+UseSerialGC
含义为:堆设置为20M,新生代设置为10MB,老年代设置为10MB,伊甸园区占新生代的80%,即8MB,两个幸存者区均为1M,GC采用Serial GC。
堆空间日志如下:
[0.159s][info ][gc,heap,exit ] Heap
[0.159s][info ][gc,heap,exit ] def new generation total 9216K, used 5360K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)
[0.159s][info ][gc,heap,exit ] eden space 8192K, 53% used [0x00000000fec00000, 0x00000000ff050cb8, 0x00000000ff400000)
[0.159s][info ][gc,heap,exit ] from space 1024K, 91% used [0x00000000ff500000, 0x00000000ff5eb4b8, 0x00000000ff600000)
[0.159s][info ][gc,heap,exit ] to space 1024K, 0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)
[0.159s][info ][gc,heap,exit ] tenured generation total 10240K, used 6144K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)
[0.159s][info ][gc,heap,exit ] the space 10240K, 60% used [0x00000000ff600000, 0x00000000ffc00030, 0x00000000ffc00200, 0x0000000100000000)
[0.159s][info ][gc,heap,exit ] Metaspace used 783K, capacity 4531K, committed 4864K, reserved 1056768K
[0.159s][info ][gc,heap,exit ] class space used 74K, capacity 402K, committed 512K, reserved 1048576K
注意这里新生代中大小为9216KB,即9MB,而非10MB,这是因为两个幸存者区同时只能使用1个,因此,新生代的可用大小为9MB。
代码用图可以表示为:
allocation4由于无法分配到伊甸园区和幸存者区,于是进行一次Young GC。
Young GC后,由于allocation1~3无法被放入幸存者区,因此它们均被转移到老年代中,allocation4被分配到伊甸园区。
GC日志分析工具
常用分析工具
代码演示
示例代码:
public class GCLogTest {
public static void main(String[] args) {
ArrayList<byte[]> list = new ArrayList<>();
for (int i = 0; i < 500; i++) {
byte[] arr = new byte[1024 * 100];//100KB
list.add(arr);
try {
Thread.sleep(50);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
}
JVM参数:-Xms60m -Xmx60m -Xlog:gc:logs/gc.log