JVM-如何分析GC日志

前言

本文算是一篇学习笔记，不详讲垃圾收集器

在Java开发的过程中，GC是一个很普遍的场景，如果不了解GC，会感觉无从下手，所以本文来梳理下

垃圾收集器

大致回顾下垃圾收集器

垃圾收集器	分类	作用位置	使用算法	特点	适用场景
Serial	串行运行	作用于新生代	复制算法	响应速度优先	适用于单CPU环境下的client环境
ParNew	并行运行	作用于新生代	复制算法	响应速度优先	多CPU环境Server模式下与CMS配合使用
Parallel Scavenge	并行运行	作用于新生代	复制算法	吞吐量优先	适用于后台运算而不需要太多交互的场景
Serial Old	串行运行	作用于老年代	标记-压缩算法	响应速度优先	适用于单CPU环境下的client环境
Parallel Old	并行运行	作用于老年代	标记-压缩算法	吞吐量优先	适用于后台运算而不需要太多交互的场景
CMS	并发运行	作用于老年代	标记-清除算法	响应速度优先	适用于互联网或B/S业务
G1	并发、并行运行	作用域新生代、老年代	标记-压缩、复制算法	响应速度优先	面向服务端应用

• 除了G1，有连线的垃圾收集器表示可以搭配使用

  • Serial/Serial Old

  • Parallel Scavenge/Parallel Old（JDK8默认垃圾收集器组合）

  • ParNew/CMS

  • Serial/CMS（JDK9已废弃）

  • ParNew/Serial Old（JDK9已废弃）

  • Serial Old有连线是因为CMS并发清理和用户线程是同时进行的，假如并发清理时，用户线程正在新增对象，此时没有内存新增，便会启动Serial Old后备方案，进行一次full gc

GC日志

ps+po

ps+po是JDK8默认的垃圾收集器组合，我们先从这对组合开始

// 配置详情
// -Xms100m -Xmx100m -XX:+PrintGCDateStamps -XX:+PrintGCDetails 
// -XX:+PrintCommandLineFlags -XX:+UseParallelGC 
public class GcTest {

    public static void main(String[] args) {
        List<byte[]> list = new ArrayList<>();

        while(true) {
            // 100K
            byte[] bytes = new byte[1024 * 100];
            list.add(bytes);
        }

    }
}
复制代码

执行代码，很快就可以打印出gc日志

ps+po Minor GC日志解析

日志	解析
2021-05-09T15:38:45.580-0800	日志打印时间，-XX:+PrintGCDateStamps：新增此配置便可打印出来
GC (Allocation Failure)	发生了一次垃圾回收，这是一次Minor GC，它不区分新生代GC还是老年代GC，括号里的内容是GC发生的原因，这里的Allocation Failure的原因是新生代中没有足够区域能够存放需要分配的数据而失效
[PSYoungGen: 2536K->496K(2560K)]	PSYoungGen：表示GC发生的区域，区域名称与使用的GC收集器是密切相关的 Serial收集器：Default New Generation 显示DefNew ParNew收集器：ParNew Parallel Scanvenge收集器：PSYoung
2536K->496K(2560K)：GC前该内存区域已使用容量 -> GC后该区域容量（该区域总容量）	总容量则会显示整个新生代内存的9/10，即是eden + from/to区，因为from、to同一时间只有一个区域会存储数
4723K->4717K(9728K)	在显示完区域容量GC的情况之后，会接着显示整个堆内存区域的GC情况：GC前堆内存已使用容量 -> 堆内存总容量
0.0013088 secs	整个GC花费的时间，单位是秒
[Times: user=0.00 sys=0.00, real=0.00 secs]	user：进程执行用户态代码（核心之外）所使用的时间，这是执行此进程所使用的实际CPU时间，其他进程和此进程阻塞的时间并不包括在内。在垃圾收集的情况下，表示GC线程执行所使用的CPU总时间 sys：进程在内核态消耗的CPU时间，即在内核执行系统调用或等待系统事件所使用的CPU时间 real：程序从开始到结束所用的时钟时间。这个时间包括其他进程使用的时间片和进程阻塞的时间（比如等待IO完成）。对于并行gc，这个数字应该接近（用户时间+系统时间）/垃圾收集器使用的线程数

ps+po Full GC日志解析

full gc的日志跟minor gc的日志是相似的

日志	解析
Full GC (Ergonomics)	发生了一次垃圾回收，这是一次Full GC，它不区分新生代GC还是老年代GC 括号里的内容是gc发生的原因，这里的Ergonomics是由于JVM的自适应调整导致的GC Full GC（System）：调用了System.gc()方法 Metadata GC Threshold：Metaspace区不够用了

public class GcTest {

    public static void main(String[] args) {
        List<byte[]> list = new ArrayList<>();
        while(true) {
            // 10K
            byte[] bytes = new byte[1024 * 100];
            list.add(bytes);
          	// 手动触发gc
            System.gc();
        }
    }
}
复制代码

可以看到gc原因开始变化

cglib动态代理不断生成类造成元空间溢出

public static void main(String[] args) {

    while (true) {
        Enhancer enhancer = new Enhancer();
        enhancer.setCallback(new CglibInterceptor());
        // 不使用缓存，不断产生新的代理对象
        enhancer.setUseCache(false);
        enhancer.setSuperclass(CglibBean.class);
        CglibBean cglibBean = (CglibBean) enhancer.create();
        cglibBean.eat();
    }
}
复制代码

可以看到gc原因发生变化

OOM的原因也发生了变化

CMS

模拟CMS gc的代码是相同的，只是垃圾收集器改成了CMS

// -Xms100m -Xmx100m -XX:+PrintGCDateStamps -XX:+PrintGCDetails 
// -XX:+PrintCommandLineFlags -XX:+UseConcMarkSweepGC
public static void main(String[] args) {
    List<byte[]> list = new ArrayList<>();

    while(true) {
        // 10K
        byte[] bytes = new byte[1024 * 100];
        list.add(bytes);
    }
}
复制代码

CMS整个过程主要是4个阶段：

• 初始标记（STW）
• 并发标记
• 重新标记（STW）
• 并发清理

查看CMS的gc日志，整个过程可以细分为7个阶段

• CMS Initial Mark：
• CMS-concurrent-mark
• CMS-concurrent-preclean
• CMS-concurrent-abortable-preclean
• CMS Final Remark
• CMS-concurrent-sweep
• CMS-concurrent-reset

关于这几个阶段各自的作用，这篇大佬的文章讲得不错www.jianshu.com/p/2a1b2f17d…

G1

在GC日志前，先大概介绍一下G1垃圾收集器

在内存空间越来越大的今天，分代收集垃圾造成的STW已经很难往下优化了，G1垃圾收集器使用了分区收集这种新的思路

在使用G1收集器时，会将整个Java堆划分成约2048个大小相同的独立Region块，每个Region块大小根据堆空间的实际大小而定，整体被控制在1MB到32MB之间，且为2到N次幂，即1MB，2MB，4MB，8MB，16MB，32MB，可以通过-XX:G1HeapRegionSize设定。所有的Region大小相同，且在JVM生命周期内不会被改变

如图所示，可以将Region分配到eden、survivor、old、humongous，humongous主要用于存放标准区域大小的50%或者比50%更大的对象，存储为一组连续区域

Rset

Region与Region之间不可能是独立的，一个Region中的对象被其它Region中的对象引用是正常的事情，如果没有任何措施，想要知道对象是否被其它Region的对象引用，需要扫描整个堆，这个方法太低效，所以G1使用Rset来记录对象之间的引用关系

如下图，每个Region都有一个Rset，Region1和Region3中的对象引用了Region2中的对象，则在Region2的Rset中记录了这个引用

Cset

每次GC时要回收的目标分区

GC回收过程

1. 当Eden区内存不足时会触发年轻代GC，G1的年轻代收集阶段是一个并行的独占式收集器，GC时会暂停所有应用线程，启动多线程执行年轻代回收
2. 当堆内存达到一定值时，开始老年代并发标记阶段
3. 标记完成马上开始混合回收过程，G1的老年代回收器不需要整个老年代回收，一次只需要扫描一小部分老年代的Region就可以了
4. 如果上述方式不能正常工作，G1就会STW，使用单线程的内存回收算法进行垃圾回收

下图是垃圾回收过程中对象复制的过程

G1GC日志

关于这些日志的意思，这位大佬的翻译文章讲得不错www.jianshu.com/p/ab37844d0…

GC easy

gc日志这么多，我们不可能人为分析，gceasy是一个比较好的gc日志分析工具

由于需要足够多的gc日志才能看出效果，本人拉取了测试环境的gc日志文件，下图是这个容器的环境配置

使用gc easy 分析gc日志

• Young Generation表示年轻代，Old Generation表示老年代，Meta Space表示元空间，Allocated表示分配的空间，Perk表示达到过的峰值
• -Xmn725M： 按照道理来说年轻代应该占241.6M的JVM堆内存，这里显示占用了217.81，是因为幸存者0区和幸存者1区同一时间只有一个区域能够存储数据，所以年轻代占用内存为725/3*0.9=217.5
• 老年代占用2/3的JVM堆内存，元空间占用1.08G的机器内存

• Throughput表示吞吐量，此处吞吐量为99.981%
• Latency表示耗时情况， Avg Pause GC Time表示平均GC耗时为10.7ms，Max Pause GC Time表示最大GC耗时为530ms
• GC Pause Duration Time Range表示GC耗时时间分布，0-100这个区间占了99.97%

Interactive Graphs每个图的含义

• Heap after GC：GC之后堆的使用情况
• Heap before GC：GC之前堆的使用情况
• GC Duration：GC持续时间
• Reclaimed Bytes：GC回收掉的垃圾对象的内存大小
• Young Gen：年轻代堆的使用情况
• Old Gen：老年代堆的使用情况
• Meta Space：元空间的使用情况
• A & P：每次GC的时候堆内存分配和晋升情况。其中红色的线表示每次GC的时候年轻代里面有多少内存(对象)晋升到了老年代

特别说明一下GC持续时间，GC一次包含多个过程，比如CMS包含初始标记，并发标记等过程，这里的GC持续时间指暂停阶段所花费的时间

GC相关统计，从左到有分别是Minor GC和Full GC总共回收的内存大小、Minor GC和Full GC累计时间大小、Minor GC和Full GC平均耗时

参考资料

blog.csdn.net/qq_40093255…

尚硅谷JVM视频