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。

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

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

一、如何打印GC日志

二、频繁YGC场景Demo

2.1 JVM 参数

2.2 Demo 示例代码

2.3 ygc日志内容

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

四、YGC深入实践思考Demo

五、频繁FGC场景Demo

5.1 JVM 参数

5.2 Demo 示例代码

5.3 fgc日志内容

5.3 老年代FGC日志深入剖析

微服务

热门文章

最新文章

相关课程

相关电子书

相关实验场景

探索云世界

热门

云计算

大数据

云原生

人工智能

数据库

开发与运维

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

一、如何打印GC日志

二、频繁YGC场景Demo

2.1 JVM 参数

2.2 Demo 示例代码

2.3 ygc日志内容

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

四、YGC深入实践思考Demo

五、频繁FGC场景Demo

5.1 JVM 参数

5.2 Demo 示例代码

5.3 fgc日志内容

5.3 老年代FGC日志深入剖析

微服务

热门文章

最新文章

相关课程

相关电子书

相关实验场景