JVM-GC日志分析

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);
        }
    }
}
  1. -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

  1. -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信息,前面带有标准时间、日志等级和日志内容所属标签,没有打印堆信息。

  1. -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信息,前面带有标准时间,以及堆的信息。

  1. -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信息,前面带有真实时间,没有打印标准时间、日志等级和日志内容所属标签。

  1. -Xms60m -Xmx60m -Xlog:gc:logs/gc.log

日志信息会输出到logs/gc.log文件中。

JDK9中JVM日志系统的更新

JVM在JDK9中采用了统一的日志系统,GC日志也归入其中,因此原有的查看GC信息的方法都被弃用或删除。
具体可以查看官方文档:

相关中文资料可以参考:

日志文件分析

通过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

评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值