JVM进阶调优系列(8)如何手把手，逐行教她看懂GC日志？| IT男的专属浪漫

读书笔记：弗洛伊德的因果论强调过去决定着现在，家庭环境尤其是父母行为对孩子的心理成长影响是巨大的。孩子表现出来的大多问题，实际是家长的问题。

    如果有一天，公司刚满38岁没多少年的前台小姐姐为你心动，除了被你经常穿拖鞋上班的帅气迷倒，还常常被你一周不洗头的执着、以及穿了三年还散发着刚出厂时候的清新味道的格子衫而着迷。

    早上她悄悄给你递纸条，告诉你她要转行学开发。你会不会手把手教她写hello world，还有她想学GC日志分析。你愿意为了她手把手逐行耐心教她讲这些技术细节吗？

    好了，也许没那么浪漫，但万一真有这好事，谁说的准！大家有必要提前整理一下。这次也是手把手投喂，工具基础已经来到第8篇。

一、如何打印GC日志

     之前系列6《一文详解JVM参数与大厂实战调优模板推荐》有相关GC log参数，这里我们选取几个最常用的作为Demo演示:

-XX:+PrintGCDetails ：打印GC的详细信息。

-XX:+PrintGCDateStamps： 打印GC日志开始的具体时间。

-XX:+PrintGCTimeStamps：打印每次GC的耗时。

-Xloggc：将GC日志保存到指定目录文件。
-XX:+PrintGCDetails ：打印GC的详细信息。-XX:+PrintGCDateStamps： 打印GC日志开始的具体时间。-XX:+PrintGCTimeStamps：打印每次GC的耗时。-Xloggc：将GC日志保存到指定目录文件。

在JVM启动参数里，增加这几个参数:

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -Xloggc:ygc-gc.log

JVM发生GC后，就可以在指定文件里查看JVM启动后，发生GC日志的全部历史记录信息。

二、频繁YGC场景Demo

    我们模拟一个堆内存大小为20mb，其中年轻代是10mb，老年代是10mb，年轻代Eden区是8mb，S0，S1分别是1mb,此外垃圾回收器选择Parnew 和CMS回收器。并设置打印GC时间戳还有GC耗时统计，并保存到特定log日志。

2.1 JVM 参数

-Xms20m -Xmx20m -Xmn10m -XX:+UseParNewGC -XX:+UseConcMarkSweepGC 
 -XX:PretenureSizeThreshold=10485760  -XX:+PrintGCDetails 
 -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps  -Xloggc:ygc-gc.log

2.2 Demo 示例代码

    通过向JVM申请年轻代空间存储多个1MB大小的数组，触发年轻代YGC，然后观察分析YGC内容。

package lading.java.jvm;
/**
 * 模拟发送YGC，并打印gc日志,内存划分：
 * 年轻代 10M；
 * 老年代 10M；
 * 大于10MB的对象直接进入老年代
 */
public class Demo003YgcLog {
    public static void main(String[] args) {
        //只新建9个1MB 对象到年轻代
        byte[] obj1Mb_1 = new byte[1024*1024];
        byte[] obj1Mb_2 = new byte[1024*1024];
        byte[] obj1Mb_3 = new byte[1024*1024];
        byte[] obj1Mb_4 = new byte[1024*1024];
        byte[] obj1Mb_5 = new byte[1024*1024];
        byte[] obj1Mb_6 = new byte[1024*1024];
        obj1Mb_5 = null;//help gc
        obj1Mb_6 = null;//help gc
        byte[] obj1Mb_7 = new byte[1024*1024];
        byte[] obj1Mb_8 = new byte[1024*1024];
        byte[] obj1Mb_9 = new byte[1024*1024];
    }
}

2.3 ygc日志内容

最后发生ygc日志内容如下：

Java HotSpot(TM) 64-Bit Server VM (25.191-b12) for bsd-amd64 JRE (1.8.0_191-b12), built on Oct  6 2018 08:37:07 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 16777216k(685664k free)
/proc/meminfo:
CommandLine flags: -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=10485760 -XX:MaxTenuringThreshold=6 -XX:NewSize=10485760 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=10485760 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC 
2024-11-05T16:24:34.926-0800: 0.110: [GC (Allocation Failure) 2024-11-05T16:24:34.927-0800: 0.110: [ParNew: 7354K->668K(9216K), 0.0035697 secs] 7354K->5790K(19456K), 0.0036905 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
Heap
 par new generation   total 9216K, used 5088K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)
  eden space 8192K,  53% used [0x00000007bec00000, 0x00000007bf051208, 0x00000007bf400000)
  from space 1024K,  65% used [0x00000007bf500000, 0x00000007bf5a71c8, 0x00000007bf600000)
  to   space 1024K,   0% used [0x00000007bf400000, 0x00000007bf400000, 0x00000007bf500000)
 concurrent mark-sweep generation total 10240K, used 5122K [0x00000007bf600000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 3013K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 334K, capacity 388K, committed 512K, reserved 1048576K

三、年轻代YGC日志深入分析

   gc日志的分析已经很贴近生产问题实战，不过这里我们主要是分享掌握如何看懂gc日志，距离我们生产实战调优、排查问题只有一步之遥，大家保持耐心。

具体gc日志观摩：

=========================================

java HotSpot(TM) 64-Bit Server VM (25.191-b12) for bsd-amd64 JRE (1.8.0_191-b12), built on Oct  6 2018 08:37:07 ...

Memory: 4k page, physical 16777216k(685664k free)

/proc/meminfo:

这段是JVM的版本信息。

=========================================

CommandLine flags: -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=10485760 ....

以上内容是启动的JVM参数也打印出来。

=========================================

2024-11-05T16:24:34.926-0800: 0.110: [GC (Allocation Failure)

这里是说内存分配失败，需要发生GC，前面是发生时间，中间有个[0.110]数值是表示当前时间距离JVM启动多久。

=========================================

2024-11-05T16:24:34.927-0800: 0.110: [ParNew: 7354K->668K(9216K), 0.0035697 secs] 7354K->5790K(19456K), 0.0036905 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]

这里是ParNew垃圾回收器在做GC，也就是YGC。

3.1、【7354K->668K(9216K), 0.0035697 secs】 ，表示年轻代可用空间总共有9216K，大约9M（Eden+一个S区=年轻代可用空间），已被占用7354K，大概7M多，本次YGC后，年轻代存活的对象大小为668K，耗时3.5697ms。按demo，如果存活对象是我们new的那几个，那至少都是1Mb以上，存活只有668k，这说明本次YGC之后，存活的668k信息已经挪到S区，如果我们的对象有存活，由于S0/1区只有1M空间肯定放不下，又么全部对象被回收，又么已经被挪到老年代。

3.2、【7354K->5790K(19456K), 0.0036905 secs】，表示整个堆内存可用空间有19456K，大概19Mb，当前堆内存被占用7354K，YGC后，存活的对象有5790K，大概5Mb多，也就是大概只有5个对象存活。看实例demo，也就是我们分配到第8个对象时候发生了YGC。存活的对象编号是是12347。

3.3、[Times: user=0.01 sys=0.01, real=0.01 secs]，这个是本次gc的时间统计。其中user=0.01表示 gc线程占用cpu耗时，sys=0.01 系统调用等待耗时， real=0.01 secs表示应用暂停耗时。

=========================================

继续，接下来日志内容为：

Heap

par new generation   total 9216K, used 5088K [0x00000007bec00000, 0x00000007bf600000, 0x00000007bf600000)

 eden space 8192K,  53% used [0x00000007bec00000, 0x00000007bf051208, 0x00000007bf400000)

 from space 1024K,  65% used [0x00000007bf500000, 0x00000007bf5a71c8, 0x00000007bf600000)

 to   space 1024K,   0% used [0x00000007bf400000, 0x00000007bf400000, 0x00000007bf500000)

这段也好理解。

3.4、【 par new generation   total 9216K, used 5088K】表示年轻代可用空间是9M，在JVM退出前，仍有大概5M的存活对象待在年轻代那里。

3.5、【eden space 8192K,  53% used】表示年轻代的Eden区 总共有8M，目前有53%大于4M空间被占用。

3.6 、【from space 1024K,  65% used】表示From区，也就是我们之前常说的S0或S1区，空间是1M，目前被占用600多KB。

3.7、【 to   space 1024K,   0% used 】表示To区有1M大小，目前是空的。这和我们之前JVM内存分代划分理论专题说的一致，S0、S1区总有一个是空的，用于存放下次YGC存活的对象。

=========================================

     YGC日志就这么多内容，是不是也很简单轻松掌握？如果大家有时间想更深入实践理解，下面给大家一个更简单的Demo代码。

四、YGC深入实践思考Demo

      分享一个更简单的demo，但是更加方便大家深入理解JVM运行机制。比如看以下demo代码，非常简单，只设置，10Mb的堆内存，年轻代和老年代各5Mb，程序尝试给2个对象分配内存。

5Mb的年轻代，分配2MB对象，会发送YGC吗？

JVM启动后，年轻代会被占用多少空间，只新增分配一个对象，年轻代占用多大空间?

年轻的YGC后，对象被回收了，还是放到哪里？

这个demo，只要实践几分钟，可以帮助大家非常清晰找到答案，并深入掌握JVM这块内存分配和GC内核原理。希望有时间的尤其PC端的同学可以实践讨论一下。

package lading.java.jvm;
/**
 * 模拟发送YGC，并打印gc日志
 * JVM 参数：-Xms10m -Xmx10m -Xmn5m -XX:SurvivorRatio=8 
 * -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:PretenureSizeThreshold=10485760 
 * -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -Xloggc:ygc-gc.log
 * 内存划分：
 * 年轻代 5M；
 * 老年代 5M；
 * 大于10MB的对象直接进入老年代
 */
public class Demo003YgcLog {
    public static void main(String[] args) throws InterruptedException {
        //只新建2个1MB 对象到年轻代
        byte[] obj1Mb_1 = new byte[1024 * 1024];
        //再次分配，会发生YGC吗？
        byte[] obj1Mb_2 = new byte[1024 * 1024];
    }
}

五、频繁FGC场景Demo

      我们模拟老年代Full GC 日志打印，其中堆内存只设置10MB，老年代和年轻代各5MB，大对象阈值3Mb，对象YGC最大年龄为5。具体JVM参数如下。

5.1 JVM 参数

-Xms10m -Xmx10m -Xmn5m -XX:SurvivorRatio=8 -XX:+UseParNewGC
 -XX:+UseConcMarkSweepGC -XX:PretenureSizeThreshold=3145728 
 -XX:MaxTenuringThreshold=5 -XX:+PrintGCDetails -XX:+PrintGCDateStamps
  -XX:+PrintGCTimeStamps -Xloggc:fgc-gc.log

5.2 Demo 示例代码

package lading.java.jvm;
/**
 * 模拟老年代Full GC 日志打印
 * 其中堆内存10MB，老年代和年轻代各5MB,大对象阈值3Mb，对象YGC最大年龄为5。
 */
public class Demo004FgcLog {
    public static void main(String[] args) {
        //对象1，直接到老年代
        byte[] obj_1Mb_1 = new byte[4 * 1024 * 1024];
        obj_1Mb_1 = null;
        //对象2能直接成功分配到年轻代?不发生GC吗
        byte[] obj_2Mb_2 = new byte[2 * 1024 * 1024];
        byte[] obj_2Mb_3 = new byte[2 * 1024 * 1024];
    }
}

5.3 fgc日志内容

Java HotSpot(TM) 64-Bit Server VM (25.191-b12) for bsd-amd64 JRE (1.8.0_191-b12), built on Oct  6 2018 08:37:07 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 16777216k(391332k free)
/proc/meminfo:
CommandLine flags: -XX:InitialHeapSize=10485760 -XX:InitialTenuringThreshold=5 -XX:MaxHeapSize=10485760 -XX:MaxNewSize=5242880 -XX:MaxTenuringThreshold=5 -XX:NewSize=5242880 -XX:OldPLABSize=16 -XX:PretenureSizeThreshold=3145728 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC 
2024-11-06T14:44:36.585-0800: 0.111: [GC (Allocation Failure) 
2024-11-06T14:44:36.585-0800: 0.111: [ParNew: 2226K->512K(4608K), 0.0014551 secs] 6322K->4759K(9728K), 0.0015496 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2024-11-06T14:44:36.587-0800: 0.113: [GC (Allocation Failure) 
2024-11-06T14:44:36.587-0800: 0.113: [ParNew (promotion failed): 2603K->2394K(4608K), 0.0015034 secs]
2024-11-06T14:44:36.588-0800: 0.115: [CMS: 4263K->2562K(5120K), 0.0019397 secs] 6850K->2562K(9728K), [Metaspace: 3003K->3003K(1056768K)], 0.0035228 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2024-11-06T14:44:36.591-0800: 0.117: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2562K(5120K)] 4638K(9728K), 0.0001905 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-11-06T14:44:36.591-0800: 0.117: [CMS-concurrent-mark-start]
Heap
 par new generation   total 4608K, used 2240K [0x00000007bf600000, 0x00000007bfb00000, 0x00000007bfb00000)
  eden space 4096K,  54% used [0x00000007bf600000, 0x00000007bf830268, 0x00000007bfa00000)
  from space 512K,   0% used [0x00000007bfa00000, 0x00000007bfa00000, 0x00000007bfa80000)
  to   space 512K,   0% used [0x00000007bfa80000, 0x00000007bfa80000, 0x00000007bfb00000)
 concurrent mark-sweep generation total 5120K, used 2562K [0x00000007bfb00000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 3013K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 334K, capacity 388K, committed 512K, reserved 1048576K

5.3 老年代FGC日志深入剖析

    也许看到这里的同学，尤其是对大项目堆内存分析优化不够熟悉的同学，可能会有疑问：我们系统业务很小，OOM没发生过，GC次数也少，学会看GC日志有什么实际意义吗？

   工作10+年或至少5+年的大厂同学，在公司业绩考核里都会面临一个技术价值问题。除了日常研发业务系统，我们还需要通过额外的技术工作，体现技术价值。比如参与开源项目研发、技术创新、技术分享，这些都依赖对核心技术的深入实践了解，所以打下坚实的技术基石，可以让我们走的更稳更远。

    说远了，继续FGC日志内容分析。开头部分和YGC的日志内容一样，这里不赘述，从FGC的部分开始。

=========================================

2024-11-06T14:44:36.585-0800: 0.111: [GC (Allocation Failure)

2024-11-06T14:44:36.585-0800: 0.111: [ParNew: 2226K->512K(4608K), 0.0014551 secs] 6322K->4759K(9728K), 0.0015496 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

2024-11-06T14:44:36.587-0800: 0.113: [GC (Allocation Failure)

2024-11-06T14:44:36.587-0800: 0.113: [ParNew (promotion failed): 2603K->2394K(4608K), 0.0015034 secs]

2024-11-06T14:44:36.588-0800: 0.115: [CMS: 4263K->2562K(5120K), 0.0019397 secs] 6850K->2562K(9728K), [Metaspace: 3003K->3003K(1056768K)], 0.0035228 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

2024-11-06T14:44:36.591-0800: 0.117: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2562K(5120K)] 4638K(9728K), 0.0001905 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

2024-11-06T14:44:36.591-0800: 0.117: [CMS-concurrent-mark-start]

5.3.1 【GC (Allocation Failure】，这里我们看到在分配第二个对象的时候就发生了YGC。

5.3.2 【ParNew (promotion failed)】，这是指发生了YGC之后存活的对象太大，在S区无法存下，需要放到老年代。但是这时候因为老年代已经放了一个4Mb的对象，没有足够空间放2Mb的新对象。这时候就需要发生FGC。

5.3.3 【CMS: 4263K->2562K(5120K), 0.0019397 secs] 6850K->2562K(9728K)】，这个是说老年代总空间是5120K(5MB)，目前被占用4263K(4Mb)，FGC后，有2562K（2MB)空间被占用，耗时1.9ms。整个堆内存有9728K(10MB)，本次FGC之前被占用6850K(6Mb)，GC后仍有2562K(2Mb)对象在堆内存里。这些数据和我们预期JVM设置一致。

5.3.4 【CMS-initial-mark: 2562K(5120K)] 4638K(9728K), 0.0001905 secs】在CMS 初始标记阶段，CMS开始标记老年代的GC roots和年轻代有多少对象存在GC roots引用。这里发现，老年代总空间是5120K(5MB)，被占用了2562K（2MB)空间被占用，耗时1.9ms。整个堆内存有9728K(10MB)，目前被占用4638K(4Mb)。

5.3.5 【CMS-concurrent-mark-start】开始并发标记阶段，开始遍历老年代被初始的标记存活的对象。

=========================================

concurrent mark-sweep generation total 5120K, used 2562K [0x00000007bfb00000, 0x00000007c0000000, 0x00000007c0000000)

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

5.3.6 【concurrent mark-sweep generation total 5120K, used 2562K】这个标识，老年代有5Mb空间，目前占用2Mb左右。

5.3.7【Metaspace  used 3013K, capacity 4496K】元数据区，总空间是4Mb，目前已使用3Mb。

=========================================

推荐阅读：

1、JVM进阶调优系列(3)堆内存的对象什么时候被回收?

2、JVM进阶调优系列(2)字节面试:JVM内存区域怎么划分，分别有什么用？

3、JVM进阶调优系列(1)类加载器原理一文讲透

4、JAVA并发编程系列(13)Future、FutureTask异步小王子