搞java开发，看懂JVM的GC日志真的很重要

我就是我 2023-07-18 11:24 2阅读 0赞

### 前言 ###

今天整理的这篇文章，整理自以前记录的日常笔记。

刚开始接触JVM时，对待GC的日志，是保持"逃避"态度的，线上部署的程序没有达到期望的运行效率，或是预期目标时，往往会把问题的矛头指向内存上。

是不是内存不够？

![【图1】][1]

GC日志怎么这么多？占用磁盘高达几个G?  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MTE4MDU_size_16_color_FFFFFF_t_70]

不想看到打印怎么多，甚至暴力的将程序日志屏蔽掉。

我也曾经这样干过，写过的程序，同样导致过内存溢出，甚至是主机宕机。

是的，java中的垃圾回收的确帮我们省了很多事，我们不像C/C++程序员一样，

需要考虑分配（malloc）内存分配与（free）释放内存，但我相信每个java开发的小伙伴都

会遇到GC问题，无论是在程序的性能优化，还是故障分析上。

我们应该在一次又一次的失误中获得经验和教训，而不是去逃避或是草草解决问题了事。  
同样的知识点，回顾两次，就会产生 1 + 1 > 2 的效应 。

所以这篇文章我们来谈谈耳熟能详的JVM的 GC日志。

### GC 日志是什么 ###

首先来说一说GC的概念， GC 就是垃圾回收 （Garbage Collection） 的缩写。

何为垃圾？

没有任何引用指向的对象，被JVM视为垃圾。

当然，对应的判定算法有：引用计数算法、可达性分析算法。  
对应的回收算法有：标记清除、复制、标记整理、分代收集算法。

那GC的日志是什么呢？

GC日志是java虚拟机产生的一种描述性的文本日志。就像我们开发java程序需要输出log日志一样。JAVA 虚拟机用GC日志来描述，垃圾回收的情况。

### minor GC 和 Major GC ###

Minor GC，表示新生代GC，指发生在新生代的垃圾收集动作，所有的Minor GC都会触发全世界的暂停（stop-the-world），停止应用程序的线程，不过这个过程非常短。

Major GC：老年代GC，指发生在老年代的 GC，也称之为 Full GC。

### GC 日志有什么用 ###

通过GC日志，我们能直观的看到内存清理的基本工作过程。

了解垃圾回收的一些行为，何时在Young（年轻代）何时在回收Old（老年代），并且展示垃圾回收使用到多少资源。

尽管现在Java程序的可视化监控工具已经很多了【介绍？】，但是 GC 日志对于开发人员来说，是我们快速定位潜在的内存故障和性能瓶颈最直观的信息之一。

### 通过GC 日志我们能获取什么信息 ###

### ES 的 GC分配失败（GC Allocation Failure） ###

遇到线上GC问题时的日志也是很宝贵的分析素材，这里的GC Allocation Failure图片引用自一位群友的ES节点GC日志。

![file][]

GC Allocation Failure 是我们经常遇到的一种GC日志。

分配失败代表着在JVM的Eden区中没有更多的空间来分配对象了，这是minor GC的正常日志。

那别光说不练，那我们来看看GC Allocation Failure的日志内容是什么样的。

![file][file 1]

是不是感觉很乱？【抠脑袋图 对话】

没关系，我们依次来分析分析。

我们按时间分割，可以知道，截图中一共有两行日志，先来看日志一：

2020-03-17T19:03:19.701+0800: 6664.686: 
    Total time for which application threads were stopped: 0.0313360 seconds
    , Stopping threads took: 0.0000925 seconds

毋庸置疑，首先映入眼帘的是带时区的日志时间。

其次 Total time for which application threads were stopped  
表示 所有应用线程暂停了 0.0313360 秒。

其中等待所有应用线程到达 【安全点】 用了0.0000925 秒。

暂停的这段时间，其实就是花在了GC上面。后续第二行的 real=0.03 secs 和这里相对应。

刚才提到了 安全点 ，那简单提一提，我们知道在 Java 的线程有几个不同的状态。也知道线程如果被 “打断” 会出现什么样的问题。所以对于设计者来说，需要让线程 “跑” 到安全点上，再停顿。当处于安全点时，线程的状态是确定的，这样JVM就可以安全的进行一些操作，比如执行垃圾回收。

安全点的位置包括：

![file][file 2]

如果有线程一直没有进入到安全点，就会导致GC时JVM停顿时间延长。

再来看日志二：

1） 2020-03-17T19:03:20.118+0800: 6665.102:
    2）[GC (Allocation Failure) 2020-03-17T19:03:20.118+0800: 6665.102: 
    3）[ParNew Desired survivor size 8716288 bytes, new threshold 6 (max 6)
    4）- age   1:    6826872 bytes,    6826872 total
    5）- age   2:    1060216 bytes,    7887088 total
    6）: 149828K->8895K(153344K), 0.0361997 secs] 
    7）6272826K->6139400K(8371584K),0.0363166 secs]
    8） [Times: user=0.07 sys=0.00, real=0.03 secs]

第一行，为日志输出的时间。

第二行，表明了进行了一次 GC 回收，注意，由于这里没有 Full 关键字 ，表明是一次 Minor GC，并指明了 GC 的时间。  
Allocation Failure则表示GC的原因是在年轻代中没有了足够的空间来存储数据了。

第三行，ParNew 同样指明了本次 GC 是发生在年轻代，并且使用的是ParNew垃圾收集器。该收集器采用复制算法回收内存，期间会停止其他工作线程，即Stop The World。

第三、四、五行，表示每次年轻代 GC 之后打印 survivor 区域内对象的年龄分布，  
threshold则表示设置的晋升老年代的年龄阈值为6。

第六行，分别表示GC前年轻代的使用容量，GC 后该区域使用容量，括号内是该区域的总容量。最后是该内存区域GC耗时，单位是秒。

![file][file 3]

第七行，分别表示堆内存在垃圾回收之间的大小、堆内存在垃圾回收之后的大小，堆区的总大小。

![file][file 4]

可以看到在 GC 后，回收对象占比很少。

第八行，显示三个耗时，分别是用户态耗时、内核态耗时、总耗时。

![file][file 5]

从以上信息我们可以分析得出以下结论：

本次 GC 新生代减少了： 149828 - 8895 = 140933K。

堆内存区域共减少了： 6272826 - 6139400 = 133426K。

![file][file 6]  
图来自网络

再把两个等号后的结果相减：  
140933 - 133426 = 7507K

说明该次共有7507K（7.3M）内存从年轻代移到了老年代，可以看出来数量并不多，说明都是生命周期短的对象，只是这种对象有很多。

我们需要的是尽量避免Full GC的发生，让对象尽可能的在年轻代就回收掉，所以这里可以稍微增加一点年轻代的大小，让那 7.3M 的数据也保存在年轻代中。

### ES 的 Old GC ###

上面介绍了 年轻代的GC日志，下面我们来说一说 老年代的 GC 日志 ，其实和年轻代分析的方法一样。

还是先列出日志：

[gc][238384] overhead, spent [2.2s] collecting in the last [2.3s]
    
    [2020-03-18T01:01:29,020][INFO ][o.e.m.j.JvmGcMonitorService]
    [eS] [gc][old][238385][160772] duration [5s], 
    
    collections [1]/[5.1s], total [5s]/[4.4d], memory [945.4mb]->[958.5mb]/[1007.3mb],
    
    all_pools {[young] [87.8mb]->[100.9mb]/[133.1mb]}{[survivor] [0b]->[0b]/[16.6mb]}{[old] [857.6mb]->[857.6mb]/[857.6mb]}

直接来解释一下吧。  
第一行指明了这是第 238384次 GC 在最近 2.3 s 内花了 2.2s 用来做垃圾收集。

相信解读过年轻代的GC，理解第二行的含义并不复杂了。

\[gc\]\[本次是 old GC\]\[这是第228385次 GC 检查\]\[从 JVM 启动至今发生的第 160772次 GC\]  
duration \[本次检查到的 GC 总耗时 5 秒，可能是多次的加和\],

collections \[从上次检查至今总共发生1次 GC\]/\[从上次检查至今已过去 5.1 秒\],

total \[本次检查到的 GC 总耗时为 5 秒\]/\[从 JVM 启动至今发生的 GC 总耗时为 4.4 天\]，

memory \[ GC 前 Heap memory 空间\]->\[GC 后 Heap memory 空间\]/\[Heap memory 总空间\],

all\_pools(分代部分的详情)

\{\[young 区\]\[GC 前 Memory \]->\[GC后 Memory\]/\[young区 Memory 总大小\] \}

\{\[survivor 区\]\[GC 前 Memory \]->\[GC后 Memory\]/\[survivor区 Memory 总大小\] \}\{\[old 区\]\[GC 前 Memory \]->\[GC后 Memory\]/\[old区 Memory 总大小\] \}

### ES 的 GC 配置 ###

![file][file 7]

\-XX:+PrintGCDetails 表示打印GC的详细日志

\-XX:+PrintGCDateStamps 表示需要展示打印GC的日期时间

\-XX:+PrintGCApplicationStoppedTime 打印垃圾回收期间程序暂停的时间

日志滚动，输出到指定的日志文件中等等配置。

### GC日志图示 ###

如果前面的介绍还没有太明白，这里附上两张GC日志的图片，以后遇到需要阅读GC日志的时候，可以用作工具查阅。

年轻代：

![file][file 8]

老年代：

![file][file 9]

### 总结（我的观点） ###

GC 涉及到的知识点很多，本文可能只是冰山一角，从GC 日志出发分析，让读者了解，GC日志中每个数字的变化，意味着什么。更多的，先前有介绍过线上 OOM 的一些排查思路和MAT 性能分析工具在实际案例中的使用，同时希望各位多多结合实际的案例来分析，做好知识储备，即是线上出了 GC 的一些问题也能做到成竹在胸，调整出最优的JVM配置，提高线上程序的运行效率，尽量避免性能上的一些故障。最后在内容上做个小结

*  本文介绍了整理这篇笔记的缘由
 *  介绍了GC日志的基本概念
 *  minor GC 和 Major GC的基本概念
 *  说明了GC 日志的作用
 *  ES 的 GC分配失败的日志解读
 *  ES 的 Old GC的日志解读。
 *  JAVA GC的图示

**搞java开发，看懂JVM的GC日志真的很重要**

[【实战】 elasticsearch 写入速度提升的案例分享][elasticsearch]

[用java做一个能赚钱的微信群聊机器人（PC协议）][java_PC]

[ Mysql百万量级数据高效导入Redis][Mysql_Redis]

[可视化界面在线生成JVM参数][JVM]

[java线上故障分析+性能调优][java]

[ELK实践攻略][ELK]

[1]: /images/20230528/e061914bcbbe4ba3a1a7667c5b0ef7b2.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MTE4MDU_size_16_color_FFFFFF_t_70]: /images/20230528/e49af3c7c5f64f09ac85bf0a9bc14659.png
[file]: /images/20230528/213ff56a19f34518b46ed86e096315ea.png
[file 1]: /images/20230528/7c7623fb6f544cac8b7bdc2880e336f4.png
[file 2]: /images/20230528/25819bd1c3f8436489a6a9195e34a496.png
[file 3]: /images/20230528/33482e8dd835466ca64077b9a215d8c7.png
[file 4]: /images/20230528/aee505ec41fd45c48973eadfa9060ee1.png
[file 5]: /images/20230528/62d6c982a95d405ba22e3eaa373f0cba.png
[file 6]: /images/20230528/b73bc2ddb2d340578b8d063e7f034cca.png
[file 7]: /images/20230528/76254e8f767d47b788241d1c221908b0.png
[file 8]: /images/20230528/34e5329d53c6455dadf2ffbc023072ce.png
[file 9]: /images/20230528/3d0e45b8836f495c960215bf614dad06.png
[elasticsearch]: https://sourl.cn/ZHcLLB
[java_PC]: https://sourl.cn/ghaHjj
[Mysql_Redis]: https://sourl.cn/BKw2vS
[JVM]: https://sourl.cn/5W79kr
[java]: https://sourl.cn/4sgiRt
[ELK]: https://sourl.cn/JJrnuW