本文已参与「新人创作礼」活动,一起开启掘金创作之路。

前言

前阵子遇到JVM内存溢出问题，跟流式处理有一定的关系，解决分析篇在后续文章会更新。前天科三路考，同事反馈海外站点主机内存告警，我还未回，同事便通过重启暂时解决。之前分析过，无内存泄漏问题，这种情况下分析gc日志是可以看到内存变化的，但已覆盖原gc日志，在此记录GC日志分析博客。
本博客涵盖 G1垃圾收集器及ParNew + Serial Old垃圾收集器GC日志分析

目的

  1. 主机应用因jvm内存挂断，可通过gc日志分析是不是堆内存无法及时回收
  2. 后期再次重启，会让同事先将gc日志先额外保存，方便后期分析
  3. 通过gc日志帮助jVM调优

GC配置参数

参数	解释
-XX:+PrintGC	打印简单GC日志。类似：-verbose:gc
-XX:+PrintGCDetails	打印GC详细信息
-XX:+PrintGCTimeStamps	输出GC的时间戳（以基准时间的形式），本人亲试JDK11版本好像不支持
-XX:+PrintGCDateStamps	输出GC的时间戳（以日期的形式），本人亲试JDK11版本好像不支持
-XX:+PrintHeapAtGC	在进行GC的前后打印出堆的信息
-Xloggc:/opt/logs/gc.log	指定输出路径收集日志到日志文件

例:

java -Xms20m -Xmx20m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:D:/logs/gc.log -jar GCTest.jar

备注: -XX:+PrintGCDateStamps/-XX:+PrintGCTimeStamps 适用JDK1.8, 注意JDK版本 ,JDK11不支持，报错如下:

Unrecognized VM option 'PrintGCDateStamps

GC日志分析

本地代码：

package com.yecun;

import java.util.ArrayList;

public class GCTest {

    public static void main(String[] args) throws InterruptedException {
        // 可回收
        HelloWorld qingfeng = new HelloWorld();
        System.out.println(qingfeng.getClass().getName());
        // list 不可回收
        ArrayList<Object> list = new ArrayList<>();
        HelloWorld helloWorld = null;
        while(true){
            helloWorld = new HelloWorld();
            list.add(helloWorld);
        }
    }
}

G1回收器GC日志分析(JDK11)

idea的jvm配置参数

-XX:+UseG1GC -Xms20m -Xmx20m -XX:NewRatio=2 -XX:+PrintGCDetails -Xloggc:D:\java_workspace\logs\gc.log

gc.log内容

[0.032s][info][gc,heap] Heap region size: 1M
[0.033s][info][gc     ] Using G1
[0.033s][info][gc,heap,coops] Heap address: 0x00000000fec00000, size: 20 MB, Compressed Oops mode: 32-bit
// 第1次回收
[0.414s][info][gc,start     ] GC(0) Pause Young (Normal) (G1 Evacuation Pause)
[0.414s][info][gc,task      ] GC(0) Using 2 workers of 10 for evacuation
[0.418s][info][gc,phases    ] GC(0)   Pre Evacuate Collection Set: 0.0ms
[0.418s][info][gc,phases    ] GC(0)   Evacuate Collection Set: 3.0ms
[0.418s][info][gc,phases    ] GC(0)   Post Evacuate Collection Set: 0.3ms
[0.418s][info][gc,phases    ] GC(0)   Other: 0.4ms
[0.418s][info][gc,heap      ] GC(0) Eden regions: 6->0(5)
[0.418s][info][gc,heap      ] GC(0) Survivor regions: 0->1(1)
[0.418s][info][gc,heap      ] GC(0) Old regions: 0->1
[0.418s][info][gc,heap      ] GC(0) Humongous regions: 0->0
[0.418s][info][gc,metaspace ] GC(0) Metaspace: 5549K->5549K(1056768K)
[0.418s][info][gc           ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 6M->1M(20M) 4.443ms
[0.418s][info][gc,cpu       ] GC(0) User=0.00s Sys=0.00s Real=0.00s
// 第2次回收
[0.766s][info][gc,start     ] GC(1) Pause Young (Normal) (G1 Evacuation Pause)
[0.766s][info][gc,task      ] GC(1) Using 2 workers of 10 for evacuation
[0.770s][info][gc,phases    ] GC(1)   Pre Evacuate Collection Set: 0.0ms
[0.770s][info][gc,phases    ] GC(1)   Evacuate Collection Set: 3.6ms
[0.770s][info][gc,phases    ] GC(1)   Post Evacuate Collection Set: 0.2ms
[0.770s][info][gc,phases    ] GC(1)   Other: 0.2ms
[0.770s][info][gc,heap      ] GC(1) Eden regions: 5->0(5)
[0.770s][info][gc,heap      ] GC(1) Survivor regions: 1->1(1)
[0.770s][info][gc,heap      ] GC(1) Old regions: 1->2
[0.770s][info][gc,heap      ] GC(1) Humongous regions: 0->0
[0.770s][info][gc,metaspace ] GC(1) Metaspace: 5550K->5550K(1056768K)
[0.770s][info][gc           ] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 6M->2M(20M) 4.305ms
[0.770s][info][gc,cpu       ] GC(1) User=0.03s Sys=0.00s Real=0.00s

以上是第一和第二次的GC日志

日志解析

[0.414s][info][gc,start ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) -------GC回收开始，暂停年轻代（只针对年轻代进行回收）
[0.414s][info][gc,task ] GC(0) Using 2 workers of 10 for evacuation -------开启2个工作线程疏散
YOUNG GC 标记阶段

  [info][gc,phases    ] GC(0)   Pre Evacuate Collection Set: 0.0ms
  [info][gc,phases    ] GC(0)   Evacuate Collection Set: 3.7ms
  [info][gc,phases    ] GC(0)   Post Evacuate Collection Set: 0.3ms

YOUNG GC 执行回收阶段

 [info][gc,heap      ] GC(0) Eden regions: 6->0(5)   ---- eden区回前6M，回收后0M，总共5M（至于为何超出5M，这个目前我不大清楚，如有知道的兄弟，评论区请留言）
 [info][gc,heap      ] GC(0) Survivor regions: 0->1(1) ---- survivor gc前0M，gc后1M
 [info][gc,heap      ] GC(0) Old regions: 0->1  ---- 老年代回收前0M，回收后1M
 [info][gc,heap      ] GC(0) Humongous regions: 0->0 ---- 大型区域（存储大对象区）
 [info][gc,metaspace ] GC(0) Metaspace: 5543K->5543K(1056768K) ---- 元空间
 [0.418s][info][gc   ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 6M->1M(20M) 4.443ms 
 ---- 本次回收前，堆空间6M，回收后1M(survivor区+old区可能不超出2M吧)，总共20M
 [0.418s][info][gc,cpu       ] GC(0) User=0.00s Sys=0.00s Real=0.00s ---- 本次回收 User：用户态消耗时间  Sys：内核耗时  Real：实际消耗时间

ParNew + Serial Old 的组合进行内存回收

idea的jvm配置参数

-Xms20m -Xmx20m -XX:+UseParNewGC -XX:NewRatio=2 -XX:+PrintGCDetails -Xloggc:D:\java_workspace\logs\gc.log

gc.log内容

[GC (Allocation Failure) [ParNew: 6146K->753K(9216K), 0.0065877 secs] 6146K->4849K(19456K),

0.0092108 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

Heap

par new generation total 9216K, used 7220K [0x00000000fec00000, 0x00000000ff600000,

0x00000000ff600000)

eden space 8192K, 78% used [0x00000000fec00000, 0x00000000ff250ea0, 0x00000000ff400000)

from space 1024K, 73% used [0x00000000ff500000, 0x00000000ff5bc488, 0x00000000ff600000)

to space 1024K, 0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)

tenured generation total 10240K, used 4096K [0x00000000ff600000, 0x0000000100000000,

0x0000000100000000)

the space 10240K, 40% used [0x00000000ff600000, 0x00000000ffa00020, 0x00000000ffa00200,

0x0000000100000000)

Metaspace used 3362K, capacity 4496K, committed 4864K, reserved 1056768K

class space used 369K, capacity 388K, committed 512K, reserved 1048576K

Java HotSpot(TM) 64-Bit Server VM warning: Using the ParNew young collector with the Serial old

collector is deprecated and will likely be removed in a future release

日志解析

例:

[GC (Allocation Failure)[ParNew: 6146K->753K(9216K), 0.0065877 secs] 6146K->4849K(19456K),

0.0092108 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

解读前，先将上述日志抽象

[a(b)[c:d->e(f), g secs] h->i(j), k secs] [Times: user:l sys=m, real=n secs]

附上含义：

a: GC 或者是 Full GC
b: 用来说明发生这次 GC 的原因，内存分配失败，EDEN区再分配会占满
c: 表示发生GC的区域，这里表示是新生代发生了GC，上面那个例子是因为在新生代中内存不够给新对象分配了，然后触发了 GC
d: GC 之前该区域已使用的容量
e: GC 之后该区域已使用的容量
f: 该内存区域的总容量
g: 表示该区域这次 GC 使用的时间
h: 表示 GC 前整个堆的已使用容量
i: 表示 GC 后整个堆的已使用容量
j: 表示 Java 堆的总容量
k: 表示 Java堆这次 GC 使用的时间
l: 代表用户态消耗的 CPU 时间
m: 代表内核态消耗的 CPU 时间
n: 整个 GC 事件从开始到结束的墙钟时间（Wall Clock Time）

以上含义，对非G1垃圾回收器生成的日志做出解释，还是挺容易分辨的

GC日志分析工具

线上分析（网址：gceasy.io/）

分析工具gceasy 界面较为简单，可选择中文版本
选择gc文件后，点击分析，结果如截图

GCViewer

GCViewer是一个小工具，可视化展示生成的详细GC输出。

GCViewer下载

解压后目录如下：截图1 截图2 启动命令

java -jar gcviewer-1.37-SNAPSHOT.jar

弹出界面返回结果

GC日志分析-JVM

前言

GC配置参数

GC日志分析

G1回收器GC日志分析(JDK11)

idea的jvm配置参数

gc.log内容

日志解析

ParNew + Serial Old 的组合进行内存回收

idea的jvm配置参数

gc.log内容

日志解析

GC日志分析工具

线上分析（网址：gceasy.io/）

GCViewer