收藏，手把手教你Java GC算法日志解读与分析

❝

可以先阅读前篇：Java GC算法背景原理与内存池划分，对于内存池的划分先有个概念后再来看各个部分的垃圾回收详情会更好

❞

文章目录

• 触发GC的示例代码
• 常见的GC日志参数
• 输出日志详情
• 指定输出GC日志文件
• 打印GC事件发生的日期和时间
• 指定堆内存的大小
• 指定垃圾收集器
• 其他参数
• GC事件的类型
• Minor GC（小型GC）
• Major GC vs. Full GC

触发GC的示例代码

为了演示需要，代码如下：

import java.util.Random;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.LongAdder;

public class GCLogAnalysis {
    private static Random random = new Random();

    public static void main(String[] args) {
        // 当前毫秒时间戳
        long startMillis = System.currentTimeMillis();
        // 持续运行毫秒数; 可根据需要进行修改
        //
        long timeoutMillis = TimeUnit.SECONDS.toMillis(1);
        // 结束时间戳
        long endMillis = startMillis + timeoutMillis;
        LongAdder counter = new LongAdder();
        System.out.println("正在执行...");
        // 缓存一部分对象; 进入老年代

        int cacheSize = 2000;
        Object[] cachedGarbage = new Object[cacheSize];
        // 在此时间范围内,持续循环
        while (System.currentTimeMillis() < endMillis) {
            // 生成垃圾对象
            Object garbage = generateGarbage(100 * 1024);
            counter.increment();
            int randomIndex = random.nextInt(2 * cacheSize);
            if (randomIndex < cacheSize) {
                cachedGarbage[randomIndex] = garbage;
            }
        }
        System.out.println("执行结束!共生成对象次数:" + counter.longValue());
    }

    // 生成对象
    private static Object generateGarbage(int max) {
        int randomSize = random.nextInt(max);
        int type = randomSize % 4;
        Object result = null;
        switch (type) {
            case 0:
                result = new int[randomSize];
                break;
            case 1:
                result = new byte[randomSize];
                break;
            case 2:
                result = new double[randomSize];
                break;
            default:
                StringBuilder builder = new StringBuilder();
                String randomString = "randomString-Anything";
                while (builder.length() < randomSize) {
                    builder.append(randomString);
                    builder.append(max);
                    builder.append(randomSize);
                }
                result = builder.toString();
                break;
        }
        return result;
    }
}

在 main 方法中，我们用一个数组来随机存放一部分生成的对象，这样可以模拟让部分对象晋升到老年代。

一般来说，Java中的大对象主要就是各种各样的数组，比如开发中最常见的字符串，实际上 String内部就是使用字符数组 char[] 来存储的。

常见的GC日志参数

我这里使用JDK命令行，可以使用 javac 工具来编译成class文件，使用 java 命令来执行class文件

JDK8以上版本，java和javac命令可以合并成一个，java命令编译和执行是一起的，执行.java文件就可以出结果

因为我这里是JDK8演示，所以就java命令执行class文件作为示范。

输出日志详情

加上启动参数 -XX:+PrintGCDetails ，打印GC日志详情，再次执行示例

D:\javaPractice\javaPracticeTest\out\production\javaPracticeTest>java -XX:+PrintGCDetails GCLogAnalysis

执行后可以看到GC的情况如下，后面我们一步步分析：

[GC (Allocation Failure) [PSYoungGen: 65024K->10735K(75776K)] 65024K->23220K(249344K), 0.0046033 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC (Allocation Failure) [PSYoungGen: 75759K->10745K(140800K)] 88244K->45325K(314368K), 0.0065771 secs] [Times: user=0.03 sys=0.03, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 140793K->10747K(140800K)] 175373K->84823K(314368K), 0.0094744 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 140795K->10742K(270848K)] 214871K->125146K(444416K), 0.0097900 secs] [Times: user=0.03 sys=0.03, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 270838K->10746K(270848K)] 385242K->200111K(460800K), 0.0159145 secs] [Times: user=0.03 sys=0.03, real=0.02 secs]
[Full GC (Ergonomics) [PSYoungGen: 10746K->0K(270848K)] [ParOldGen: 189365K->166267K(326656K)] 200111K->166267K(597504K), [Metaspace: 2608K->2608K(1056768K)], 0.021
6138 secs] [Times: user=0.11 sys=0.01, real=0.02 secs]
[GC (Allocation Failure) [PSYoungGen: 260096K->83528K(540672K)] 426363K->249795K(867328K), 0.0181100 secs] [Times: user=0.05 sys=0.02, real=0.02 secs]
[GC (Allocation Failure) [PSYoungGen: 540232K->102898K(591360K)] 706499K->357559K(918016K), 0.0314269 secs] [Times: user=0.09 sys=0.03, real=0.03 secs]
[Full GC (Ergonomics) [PSYoungGen: 102898K->0K(591360K)] [ParOldGen: 254661K->278543K(483840K)] 357559K->278543K(1075200K), [Metaspace: 2608K->2608K(1056768K)], 0.0
355931 secs] [Times: user=0.13 sys=0.01, real=0.04 secs]
[GC (Allocation Failure) [PSYoungGen: 488448K->140935K(949760K)] 766991K->419478K(1433600K), 0.0328920 secs] [Times: user=0.03 sys=0.08, real=0.03 secs]
[GC (Allocation Failure) [PSYoungGen: 925831K->183280K(968192K)] 1204374K->545835K(1452032K), 0.0670426 secs] [Times: user=0.05 sys=0.11, real=0.07 secs]
[GC (Allocation Failure) [PSYoungGen: 968176K->247283K(1060352K)] 1330731K->655186K(1544192K), 0.0844278 secs] [Times: user=0.05 sys=0.11, real=0.08 secs]
[Full GC (Ergonomics) [PSYoungGen: 247283K->0K(1060352K)] [ParOldGen: 407903K->374258K(601600K)] 655186K->374258K(1661952K), [Metaspace: 2608K->2608K(1056768K)], 0.
0570233 secs] [Times: user=0.13 sys=0.00, real=0.06 secs]
执?结束!共生成对象次数:12932
Heap
 PSYoungGen      total 1060352K, used 32874K [0x000000076b600000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 813056K, 4% used [0x000000076b600000,0x000000076d61aae8,0x000000079d000000)
  from space 247296K, 0% used [0x00000007b0e80000,0x00000007b0e80000,0x00000007c0000000)
  to   space 286720K, 0% used [0x000000079d000000,0x000000079d000000,0x00000007ae800000)
 ParOldGen       total 601600K, used 374258K [0x00000006c2200000, 0x00000006e6d80000, 0x000000076b600000)
  object space 601600K, 62% used [0x00000006c2200000,0x00000006d8f7cb40,0x00000006e6d80000)
 Metaspace       used 2615K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 288K, capacity 386K, committed 512K, reserved 1048576K

可以看到，使用启动参数 -XX:+PrintGCDetails ，发生GC时会输出相关的GC日志。

❝

这个参数的格式为: -XX:+ ，这个加号+是一个布尔值开关，关闭就是减号-

❞

来分析一下日志：

[GC (Allocation Failure) [PSYoungGen: 65024K->10735K(75776K)] 65024K->23220K(249344K), 0.0046033 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

• [GC (Allocation Failure)] 表示GC的原因是内存分配失败

• [PSYoungGen: 65024K->10735K(75776K)] 表示GC前年轻代占用内存65024K，GC后年轻代占用内存为10735K，年轻代总内存75776K

• 65024K->23220K(249344K) 表示GC前占用的堆内存是65024K，GC后占用的堆内存为23220K，此时总堆内存为249344K。

细心的朋友可以观察到，每次GC后，年轻代、老年代和堆内存容量都在扩大，那是因为jvm有自适应参数，可以关掉-XX:-UseAdaptiveSizePolicy，这样容量就是一样的了

java -XX:+PrintGCDetails -XX:-UseAdaptiveSizePolicy GCLogAnalysis

如果大家看了我前一篇文章：Java GC算法背景原理与内存池划分https://mp.weixin.qq.com/s/0VwbT_hYO9aw-JIQeIiY5A我在里面提到“如果对象经历了一定的GC次数后仍然存活，那么它们就会挪到老年代。比如默认情况下是15次”，结果我们观察前面两次Full GC日志发现，GC不到15次，结果年轻代就挪到老年代了

[Full GC (Ergonomics) [PSYoungGen: 10746K->0K(270848K)] [ParOldGen: 189365K->166267K(326656K)] 200111K->166267K(597504K), [Metaspace: 2608K->2608K(1056768K)], 0.021
6138 secs] [Times: user=0.11 sys=0.01, real=0.02 secs]
......
[Full GC (Ergonomics) [PSYoungGen: 102898K->0K(591360K)] [ParOldGen: 254661K->278543K(483840K)] 357559K->278543K(1075200K), [Metaspace: 2608K->2608K(1056768K)], 0.0
355931 secs] [Times: user=0.13 sys=0.01, real=0.04 secs]
......

第一次Full GC根据日志还看不出是否年轻代对象有移动到老年代，第二次就看得出了，ParOldGen: 254661K->278543K(483840K)，经过Full GC后，老年代占用的内存居然还增加了，这就是年轻代对象提升到老年代的结果。

从上面日志可以计算出，第二次Full GC时，年轻代对象全部晋升到老年代。

为什么GC不到15次就提升了呢？15是最大值，到了15次是强制提升到老年代，但是不代表GC小于15次时，年轻代对象就不提升到老年代。如果存活区S0和S1空间不足以存放这些年轻代的对象，提升到老年代的动作会更早的进行。

在程序执行完成后、JVM关闭前，还会输出各个内存池的使用情况， 从最后面的输出中可以看到。下面我们来简单解读上面输出的堆内存信息。

「Heap 堆内存使用情况」

Heap
 PSYoungGen      total 1060352K, used 32874K [0x000000076b600000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 813056K, 4% used [0x000000076b600000,0x000000076d61aae8,0x000000079d000000)
  from space 247296K, 0% used [0x00000007b0e80000,0x00000007b0e80000,0x00000007c0000000)
  to   space 286720K, 0% used [0x000000079d000000,0x000000079d000000,0x00000007ae800000)

• PSYoungGen，年轻代总计 1060352K，使用量 32874K，后面的方括号中是内存地址信息
• 其中 eden space 占用了 813056K， 其中 4% used
• 其中 from space 占用了 247296K， 其中 0% used
• 其中 to space 占用了 286720K， 其中 0% used

 ParOldGen       total 601600K, used 374258K [0x00000006c2200000, 0x00000006e6d80000, 0x000000076b600000)
  object space 601600K, 62% used [0x00000006c2200000,0x00000006d8f7cb40,0x00000006e6d80000)

• ParOldGen， 老年代总计 total 601600K， 使用量 374258K
• 其中 object space 占用了 601600K， 其中 62% used

 Metaspace       used 2615K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 288K, capacity 386K, committed 512K, reserved 1048576K

• Metaspace， 元数据区总计使用了 2615K， 容量是 4486K， JVM保证可用的大小是 4864K， 保留空间1056768K
• 其中 class space 使用了 288K， capacity 386K

指定输出GC日志文件

我们在前面的基础上， 加上启动参数 -Xloggc:gc.demo.log

java -XX:+PrintGCDetails -Xloggc:gc.demo.log  GCLogAnalysis

❝

提示: 从JDK8开始，支持使用 %p ， %t 等占位符来指定GC输出文件。分别表示进程pid和启动时间 戳。例如: -Xloggc:gc.%p.log ; -Xloggc:gc-%t.log ; 在某些情况下，将每次JVM执行的GC日志输出到不同的文件可以方便排查问题。如果业务访问量大，导致GC日志文件太大，可以开启GC日志轮换，分割成多个文件，可以参考：https://blog.gceasy.io/2016/11/15/rotating-gc-log-files

❞

Java HotSpot(TM) 64-Bit Server VM (25.212-b10) for windows-amd64 JRE (1.8.0_212-b10), built on Apr  1 2019 22:50:23 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16633820k(5272488k free), swap 24466864k(4759596k free)
CommandLine flags: -XX:InitialHeapSize=266141120 -XX:MaxHeapSize=4258257920 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
0.119: [GC (Allocation Failure) [PSYoungGen: 64788K->10731K(75776K)] 64788K->22484K(249344K), 0.0046170 secs] [Times: user=0.00 sys=0.02, real=0.00 secs] 
0.137: [GC (Allocation Failure) [PSYoungGen: 75705K->10734K(140800K)] 87457K->40418K(314368K), 0.0059229 secs] [Times: user=0.02 sys=0.03, real=0.01 secs] 
0.177: [GC (Allocation Failure) [PSYoungGen: 140777K->10739K(140800K)] 170461K->81464K(314368K), 0.0095714 secs] [Times: user=0.00 sys=0.01, real=0.01 secs] 
0.203: [GC (Allocation Failure) [PSYoungGen: 140787K->10742K(270848K)] 211512K->119655K(444416K), 0.0083573 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
0.275: [GC (Allocation Failure) [PSYoungGen: 270838K->10735K(270848K)] 379751K->197582K(457728K), 0.0161735 secs] [Times: user=0.02 sys=0.03, real=0.02 secs] 
0.291: [Full GC (Ergonomics) [PSYoungGen: 10735K->0K(270848K)] [ParOldGen: 186846K->168343K(332288K)] 197582K->168343K(603136K), [Metaspace: 2608K->2608K(1056768K)], 0.0242948 secs] [Times: user=0.13 sys=0.00, real=0.02 secs] 
0.353: [GC (Allocation Failure) [PSYoungGen: 260091K->91088K(540160K)] 428435K->259431K(872448K), 0.0151566 secs] [Times: user=0.02 sys=0.05, real=0.01 secs] 
0.485: [GC (Allocation Failure) [PSYoungGen: 540112K->109043K(593920K)] 708455K->361812K(926208K), 0.0424333 secs] [Times: user=0.02 sys=0.11, real=0.04 secs] 
0.528: [Full GC (Ergonomics) [PSYoungGen: 109043K->0K(593920K)] [ParOldGen: 252769K->275830K(484352K)] 361812K->275830K(1078272K), [Metaspace: 2608K->2608K(1056768K)], 0.0449918 secs] [Times: user=0.11 sys=0.02, real=0.04 secs] 
0.660: [GC (Allocation Failure) [PSYoungGen: 484864K->139121K(934400K)] 760694K->414951K(1418752K), 0.0349132 secs] [Times: user=0.03 sys=0.06, real=0.04 secs] 
0.829: [GC (Allocation Failure) [PSYoungGen: 902513K->187385K(950784K)] 1178343K->544621K(1435136K), 0.0657464 secs] [Times: user=0.09 sys=0.11, real=0.06 secs] 
0.991: [GC (Allocation Failure) [PSYoungGen: 950777K->251378K(1020416K)] 1308013K->654723K(1504768K), 0.0679324 secs] [Times: user=0.08 sys=0.13, real=0.07 secs] 
1.059: [Full GC (Ergonomics) [PSYoungGen: 251378K->0K(1020416K)] [ParOldGen: 403344K->371836K(604672K)] 654723K->371836K(1625088K), [Metaspace: 2608K->2608K(1056768K)], 0.0540675 secs] [Times: user=0.19 sys=0.00, real=0.05 secs] 
Heap
 PSYoungGen      total 1020416K, used 30969K [0x000000076b600000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 769024K, 4% used [0x000000076b600000,0x000000076d43e698,0x000000079a500000)
  from space 251392K, 0% used [0x00000007b0a80000,0x00000007b0a80000,0x00000007c0000000)
  to   space 308736K, 0% used [0x000000079a500000,0x000000079a500000,0x00000007ad280000)
 ParOldGen       total 604672K, used 371836K [0x00000006c2200000, 0x00000006e7080000, 0x000000076b600000)
  object space 604672K, 61% used [0x00000006c2200000,0x00000006d8d1f230,0x00000006e7080000)
 Metaspace       used 2615K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 288K, capacity 386K, committed 512K, reserved 1048576K

我们可以发现， 加上 -Xloggc: 参数之后， GC日志信息输出到日志文件中

文件里最前面是JVM相关信息， 比如内存页面大小， 物理内存大小， 剩余内存等信息

然后是 CommandLine flags 这部分内容。在分析GC日志文件时，命令行参数也是一项重要的参考。因为可能你拿到了日志文件，却不知道线上的配置，日志文件中打印了这个信息，能有效减少分析排查时间。比如你可以看到用了哪些GC日志参数

指定 -Xloggc: 参数，自动加上了 -XX:+PrintGCTimeStamps 配置，观察GC日志文件可以看到， 每一行前面多了一个时间戳（如 0.119: ），表示JVM启动后经过的时间（单位秒）

细心的同学还可以发现，JDK8默认使用的垃圾收集器参数: -XX:+UseParallelGC

打印GC事件发生的日期和时间

在前面的基础上，加上启动参数 -XX:+PrintGCDateStamps ，再次执行

java -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:gc.demo.log  GCLogAnalysis

加上 -XX:+PrintGCDateStamps 参数之后，GC日志每一行前面，都打印了GC发生时的具体时间。如 2021-12-16T15:52:22.926+0800 ，表示的是：东8区时间2021年12月16日15:52:22秒.926毫秒

指定堆内存的大小

从前面的示例中可以看到输出GC日志文件时有的 CommandLine flags 信息。

即使我们没有指定堆内存，JVM在启动时也会自动算出一个默认值出来。例如：-XX:InitialHeapSize=266141120 -XX:MaxHeapSize=4258257920 等价于 -Xms256m -Xmx4g 配置。

我们现在继续增加参数，这次加上启动参数 -Xms512m -Xmx512m ，再次执行

java -Xms512m -Xmx512m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:gc.demo.log  GCLogAnalysis

此时堆内存的初始值和最大值都是512MB。具体的参数可根据实际需要配置，我们为了演示，使用了一个较小的堆内存配置，实际肯定比这大

指定垃圾收集器

一般来说，使用JDK8时我们可以使用以下几种垃圾收集器：

 -XX:+UseSerialGC 
 -XX:+UseParallelGC 
 -XX:+UseParallelGC  -XX:+UseParallelOldGC 
 -XX:+UseConcMarkSweepGC 
 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC 
 -XX:+UseG1GC

• 使用串行垃圾收集器：-XX:+UseSerialGC
• 使用并行垃圾收集器：-XX:+UseParallelGC 和 -XX:+UseParallelGC -XX:+UseParallelOldGC 是等价的, 可以通过GC日志文件中的flags看出来。
• 用CMS垃圾收集器：-XX:+UseConcMarkSweepGC 和 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC 是等价的。但如果只指定 -XX:+UseParNewGC 参数则老年代GC会 使用SerialGC。使用CMS时，命令行参数中会自动计算出年轻代、老年代的初始值和最大值，以及最大晋升阈值等信息（例如 -XX:MaxNewSize=178958336 -XX:NewSize=178958336 -XX:OldSize=357912576 ）。
• 使用 G1垃圾收集器：-XX:+UseG1GC 。原则上不能指定G1垃圾收集器的年轻代大小，否则不仅是画蛇添足，更是自废武功了。因为G1的回收方式是小批量划定区块（region）进行，可能一次普通GC中 既有年轻代又有老年代，可能某个区块一会是老年代，一会又变成年轻代了。

❝

如果使用不支持的GC组合，会启动失败，报fatal错误。

❞

其他参数

JVM里还有一些GC日志相关的参数， 例如：

• -XX:+PrintGCApplicationStoppedTime 可以输出每次GC的持续时间和程序暂停时间；
• -XX:+PrintReferenceGC 输出GC清理了多少引用类型。

❝

大部分情况下，配置GC参数并不是越多越好。原则上只配置最重要的几个参数即可，其他的都保持默认值。

❞

GC事件的类型

一般来说，垃圾收集事件(Garbage Collection events)可以分为三种类型：

• Minor GC(小型GC)
• Major GC(大型GC)
• Full GC(完全GC)

虽然 Minor GC ， Major GC 和 Full GC 这几个词汇到处都在用，但官方并没有给出标准的定义。这些术语出现在官方的各种分析工具和垃圾收集日志中，并不是很统一。官方的文档和工具之间也常常混淆，这些混淆甚至根植于标准的JVM工具中。

❝

MinorGC 称为 小型GC ，还是 次要GC 更合理呢? 辨析：在大部分情况下， 发生在年轻代的 Minor GC 次数更多， 有些文章将次数更多的GC称为次要 GC 明显是不太合理的。
在这里

• 将 Minor GC 翻译为小型GC ，而不是次要GC；
• 将 Major GC 翻译为大型GC， 而不是主要GC；
• 将 Full GC 翻译为完全GC，有时候也直接称为 Full GC。

❞

Minor GC（小型GC）

收集年轻代内存的GC事件称为 Minor GC 。关于 Minor GC 事件， 我们需要了解一些相关的内容：

1. 当JVM无法为新对象分配内存空间时就会触发 Minor GC （ 一般就是 Eden 区用满了）。如果对象的分配速率很快， 那么 Minor GC 的次数也就会很多，频率也就会很快。
2. Minor GC 事件不处理老年代， 所以会把所有从老年代指向年轻代的引用都当做 GC Root 。从年 轻代指向老年代的引用则在标记阶段被忽略。
3. 与我们一般的认知相反， Minor GC 每次都会引起STW停顿（stop-the-world）， 挂起所有的应用线程。对大部分应用程序来说， Minor GC 的暂停时间可以忽略不计，因为 Eden 区里面的对象大部分都是垃圾，也不怎么复制到存活区/老年代。但如果不符合这种情况，那么很多新创建的对象就不能被 GC清理， Minor GC 的停顿时间就会增大，就会产生比较明显的GC性能影响。

❝

简单定义：Minor GC 清理的是年轻代，又或者说 Minor GC 就是 年轻代GC （ Young GC ，简称YGC）

❞

Major GC vs. Full GC

值得一提的是，这几个术语都没有正式的定义–无论是在JVM规范中还是在GC论文中。

我们知道，除了 Minor GC 外，另外两种GC事件则是：

• Major GC(大型GC) ：清理老年代空间（Old Space）的GC事件。
• Full GC(完全GC) ：清理整个堆内存空间的GC事件，包括年轻代空间和老年代空间。

其实 Major GC 和 Full GC 有时候并不能很好地区分。更复杂的情况是， 很多 Major GC 是由Minor GC 触发的，所以很多情况下这两者是不可分离的。

另外，像G1这种垃圾收集算法，是每次找一小部分区域来进行清理，这部分区域中可能有一部分是年轻代，另一部分区域属于老年代。

所以我们不要太纠结具体是叫 Major GC 呢还是叫 Full GC ，它们一般都会造成单次较长时间的STW 暂停。所以我们需要关注的是：某次GC事件，是暂停了所有线程、进而对系统造成了性能影响呢，还是与其他业务线程并发执行、暂停时间几乎可以忽略不计。