学习比较JVM篇（六）：解读GC日志

一、前言

在之前的文章中，我们对JVM的结构、垃圾回收算法、垃圾回收器做了一些列的讲解，同时也使用了JVM自带的命令行工具进行了实际操作。今天我们继续讲解JVM。

我们学习JVM的目的是为了了解JVM，然后优化对应的参数。那么如何了解JVM运行的状态呢，日志就是一个很好的入口。和我们写的程序一样，JVM本身也是一个程序，只不过这个程序的作用是为了运行我们写的Java代码，既然是程序，那么运行的过程中肯定是会产生日志，今天我们要讲解的就是GC日志。

Java、Python等这些高级语言，之所以相对上手简单有一部分的原因就是因为其自带的垃圾回收机制，让程序员不用再手动的管理内存，对于我们开发人员来说就好比是一个黑盒，但是很多时候我们又需要知道垃圾回收是怎么进行的，此时我们就需要借助GC日志，话不多说让我们开始吧。

二、GC日志

所谓GC日志，值得就是垃圾回收器在运行过程中产生的日志，如果想要查看运行中GC产生的日志，我们就需要在启动参数上配置对应的属性。这里我们从一个简单的Demo入手

public class HeapOOMDemo {

    // 模拟大对象的大小，这里设置为 1MB
    private static final int _1MB = 1024 * 1024;

    public static void main(String[] args) {
        // 用于存储对象的列表
        List<byte[]> list = new ArrayList<>();
        // 循环创建对象
        for (int i = 0; ; i++) {
            // 每次创建一个 1MB 大小的对象
            byte[] bigObject = new byte[_1MB];
            list.add(bigObject);
            try {
                // 模拟业务处理延迟
                Thread.sleep(10);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    }
}

这段代码非常简单，就是一个死循环一直不断的往List中添加对象，同时我们设置启动参数

-Xms20m -Xmx20m -Xmn1m -XX:+PrintGCDetails -XX:+PrintGCDateStamps

参数	含义	作用	示例值说明
`-Xms20m`	设定 JVM 启动时的初始堆内存大小	避免程序运行初期频繁进行内存分配和调整，提升性能	`20m` 表示初始堆内存为 20MB
`-Xmx20m`	设定 JVM 所能使用的最大堆内存大小	限制 JVM 堆内存使用上限，防止系统内存耗尽；若与 `-Xms` 设为相同值，可减少运行时堆内存大小调整带来的性能开销	`20m` 表示最大堆内存为 20MB
`-Xmn1m`	设定新生代的大小	新生代是新创建对象存储区域，合理设置其大小可提高垃圾回收效率	`1m` 表示新生代大小为 1MB
`-XX:+PrintGCDetails`	让 JVM 在进行垃圾回收时打印详细的 GC 信息	用于分析程序的内存使用状况和垃圾回收性能，包含堆内存各区域 GC 前后使用情况、GC 类型、触发原因及耗时等	无
`-XX:+PrintGCDateStamps`	在 GC 日志中添加时间戳，精确到日期和时间	便于确定 GC 发生的具体时间，结合系统负载和业务操作分析 GC 与系统行为的关联	无

接着我们运行这个Demo，很显然会抛出OOM，我们的重点是上面的GC日志

三、日志解读

完整的GC日志如下

2025-04-07T08:49:00.478-0800: [GC (Allocation Failure) [PSYoungGen: 512K->495K(1024K)] 512K->531K(19968K), 0.0020026 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2025-04-07T08:49:00.493-0800: [GC (Allocation Failure) [PSYoungGen: 1007K->495K(1024K)] 1043K->587K(19968K), 0.0005194 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2025-04-07T08:49:00.653-0800: [GC (Allocation Failure) [PSYoungGen: 1007K->495K(1024K)] 9291K->9027K(19968K), 0.0026903 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2025-04-07T08:49:00.693-0800: [GC (Allocation Failure) [PSYoungGen: 1007K->495K(1024K)] 12611K->12339K(19968K), 0.0014364 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2025-04-07T08:49:00.735-0800: [GC (Allocation Failure) [PSYoungGen: 1007K->495K(1024K)] 16947K->16675K(19968K), 0.0020088 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 
2025-04-07T08:49:00.773-0800: [GC (Allocation Failure) [PSYoungGen: 845K->511K(1024K)] 19073K->18864K(19968K), 0.0030740 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2025-04-07T08:49:00.776-0800: [GC (Allocation Failure) [PSYoungGen: 511K->224K(1024K)] 18864K->18888K(19968K), 0.0005910 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2025-04-07T08:49:00.777-0800: [Full GC (Allocation Failure) [PSYoungGen: 224K->0K(1024K)] [ParOldGen: 18664K->18642K(18944K)] 18888K->18642K(19968K), [Metaspace: 5256K->5256K(1056768K)], 0.0090459 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2025-04-07T08:49:00.786-0800: [GC (Allocation Failure) [PSYoungGen: 0K->0K(1024K)] 18642K->18642K(19968K), 0.0003195 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2025-04-07T08:49:00.787-0800: [Full GC (Allocation Failure) [PSYoungGen: 0K->0K(1024K)] [ParOldGen: 18642K->18548K(18944K)] 18642K->18548K(19968K), [Metaspace: 5256K->5256K(1056768K)], 0.0074082 secs] [Times: user=0.03 sys=0.01, real=0.01 secs]

接下来我们详细的解读一下这个日志

2025-04-07T08:49:00.478-0800:[GC (Allocation Failure) [PSYoungGen: 512K->495K(1024K)] 512K->531K(19968K), 0.0020026 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

（1）首先第一次GC发生在 2025-04-07 08:49:00.478

（2）GC (Allocation Failure：GC的原因是因为分配失败，这里需要分析一下，我们设置的堆内存为20M，新生代和老年代默认比例是1:2，但是我们这里设置了新生代为1M。一开始我们就创建了一个List对象会占用一部分内存，然后又尝试去新建一个1M的对象，此时新生代肯定是装不下了（因为总共就1M），所以触发了MinorGC

（3）第三部分：PSYongGen表示年轻代采用的是Parallel Scavenge垃圾收集器，第一次MinorGC后，新生代的内存从使用了512K变成了使用了495K(总内存是1024K)，由此我们可以推断出我们的对象其实并没有创建在新生代（压根不够）而是直接进入了老年代。

补充说明

tips：这里要补充说明一点，很多时候我们会认为对象初始都是在新生代的，这个不一定某些大对象会直接创建在堆内存（可配），同时JVM也有动态年龄机制，在进行Minor GC 时，JVM 会对 Survivor区（新生代中用于存放存活对象的区域）中所有对象按照年龄从小到大进行排序，然后计算不同年龄对象的大小总和。当某个年龄及小于该年龄的所有对象大小总和超过了 Survivor 区一半的空间时，大于等于该年龄的对象就会直接晋升到老年代，而不需要等到达到 MaxTenuringThreshold 所设定的年龄。

（4）忽略其他的MinorGC，直接进入FullGC

2025-04-07T08:49:00.777-0800: [Full GC (Allocation Failure) [PSYoungGen: 224K->0K(1024K)] [ParOldGen: 18664K->18642K(18944K)] 18888K->18642K(19968K), [Metaspace: 5256K-5256K(1056768K)], 0.0090459 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]

解读：很明显从日志里可以看出，这次触发的是Full GC，原因也很明显分配失败。FullGC是整堆的回收，所以也会对年轻代进行回收。

年轻代：年轻代被整体回收，从使用了224K变成了使用0K；

老年代：而老年代从使用了18664K变成使用了18642K（很明显效果并不好，因为在当前Demo里我们的创建的对象并不是垃圾对象）。

Metaspace（元空间）：元空间并没有什么影响没变

（5）最后一次FullGC：2025-04-07T08:49:00.787-0800: [Full GC (Allocation Failure) [PSYoungGen: 0K->0K(1024K)] [ParOldGen: 18642K->18548K(18944K)] 18642K->18548K(19968K), [Metaspace: 5256K->5256K(1056768K)], 0.0074082 secs] [Times: user=0.03 sys=0.01, real=0.01 secs]

从这段日志里可以看出老年代实在是回收不动了，因为源源不断的对象被新建出来了存放到了老年代，一种产生了OOM。

Heap
 PSYoungGen      total 1536K, used 540K [0x00000007bfe00000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 1024K, 5% used [0x00000007bfe00000,0x00000007bfe0ee58,0x00000007bff00000)
  from space 512K, 93% used [0x00000007bff80000,0x00000007bfff81f0,0x00000007c0000000)
  to   space 512K, 0% used [0x00000007bff00000,0x00000007bff00000,0x00000007bff80000)
 ParOldGen       total 18432K, used 18089K [0x00000007bec00000, 0x00000007bfe00000, 0x00000007bfe00000)
  object space 18432K, 98% used [0x00000007bec00000,0x00000007bfdaa490,0x00000007bfe00000)
 Metaspace       used 5231K, capacity 5246K, committed 5504K, reserved 1056768K
  class space    used 609K, capacity 618K, committed 640K, reserved 1048576K

最后附上完整的使用情况。