揪出一个导致GC慢慢变长的JVM设计缺陷

本文涉及的产品
日志服务 SLS,月写入数据量 50GB 1个月
简介: 分享的内容和 YGC(Young GC)有关,是我最近碰到的一个案例,希望将排查思路分享给大家,如果大家后面碰到类似的问题,可以直接作为一个经验来排查。

今天要给大家分享的内容和 YGC(Young GC)有关,是我最近碰到的一个案例,希望将排查思路分享给大家,如果大家后面碰到类似的问题,可以直接作为一个经验来排查。

我之前在公众号里其实写过几篇 YGC 的文章,也许其中有人已经看过了,没看过的可以去看看,那两个坑在这里就不再描述,大家可以直接当经验使用。

Java 堆分为新生代和老生代,YGC 其实就是针对新生代的垃圾回收,对象都是优先在新生代分配的,因此当新生代内存不够分配的时候就会触发垃圾回收,正常情况下可能触发一次 YGC 就可以解决问题并正常分配的,当然也有极端情况可能要进行大扫除,对整个堆进行回收,也就是我们说的 Full GC,这种情况发生就会比较悲剧了。

这里再提一下,YGC 也是会 STW(stop the world) 的,也就是会暂停整个应用,不要觉得 YGC 发生频繁不是问题。

说实话我比较不喜欢排查 YGC 的问题,因为 YGC 的日志太简单了,正常情况下只能知道新生代内存从多少变到了多少,花了多长时间,再无其它信息了。

所以当有人来咨询为什么我的程序 YGC 越来越长的问题的时候,我其实是抗拒的,不过也无奈,总得尝试去帮人家解决,包括前面说的那两个问题,也是费了不少精力查出来的,希望大家珍惜。。。

有些时候你越想逃避,偏偏就会找上你,YGC 的问题最近说实话找我的挺多的,不过有好些都是踩过的坑,所以能顺利帮人家解决,但是今天要说的这个问题是之前从未碰到过的,是一个全新的问题,所以也费了我不少精力,也因为其他问题要查被拖延了几天。

这个问题最终排查下来其实是 JVM 本身设计上面的一个缺陷,我改天也会提到 openjdk 社区去和大家一起讨论下这个设计,希望能彻底根治这个问题。

这个问题现象也很明显,就是发现 YGC 的时间越来越长,从 20ms 慢慢增加到100ms+,甚至还一直在涨。

不过这个增长过程还是挺缓慢的,其实 YGC 时间在几十毫秒我个人认为算正常现象,没必要去深究,再说了还是经过压测了一个晚上才涨上来的,所以平时应该也不是啥问题吧,不过这次正巧赶上年中大促,所以大家对时间也比较敏感,便接手来排查这个案例了。

首先排除了之前碰到的几种情况,然后我要同事加了一个我们 alijdk 特定的参数,可以打印 YGC 过程里具体各个阶段的耗时情况,可惜的是并没有找出问题,因为我们漏掉了一些点,导致没有直接定位出来。

于是我怀疑那些没跟踪到的逻辑,首先怀疑的就是引用这块的处理,所以叫同事加上了 -XX:+PrintReferenceGC 这个参数,这个参数会打印各种引用的处理时间,大概如下:

image.png

从当时的那个日志里,我发现了一个现象,就是随着 YGC 时间的增长,JNI Weak Reference 的处理耗时也在不断增长,所以基本就定位到了 YGC 增长的直接原因。

JNI Weak Reference 到底是什么呢?大家都知道 Java 层面有各种引用,包括 SoftReference,WeakReference 等,其中 WeakReference 可以保证在 GC 的时候不会阻碍其引用对象的回收,同样的在 native 代码里,我们也可以做类似的事情,有个叫做 JNIHandles::make_weak_global 的方法来达到这样的效果。

于是我开始修改 JVM,尝试打印一些信息出来,不知道大家注意过,我们 dump 线程的时候,使用 jstack 命令,最后一条输出里会看到类似 JNI global references: 328 的日志,这里其实就是打印了 JNI 里的两种全局引用总数,分别是 _global_handles 和 _weak_global_handles。

于是尝试将这两种情况分开来,看具体哪种有多少个,于是改了第一个版本,从修改之后的输出来看,_global_handles 的引用个数基本稳定不变,但是 _weak_global_handles 的变化却比较明显。

至此也算佐证了 JNI Weak Reference的问题,于是我想再次修改 JVM,打印了这些 JNI Weak Reference 引用的具体对象是什么对象。

在每次我执行 jstack 时,就会顺带把那些对象都打印出来,当然那个时候是为了性能,毕竟程序还跑在线上,不敢动太大,比如要是大量输出日志不可控,那就麻烦了,所以就借助 jstack 来手动触发这个逻辑。

从输出来看,看到了大量的下面的内容:
image.png

于是询问同事是不是存在大量的 Java 对 JavaScript 的调用,被告知确实有使用,那问题点基本算定位到了,我马上要同事针对他们的用法写一个简单的 demo 出来复现下问题。

没想到很快就写好,而且真的很容易复现,大概逻辑如下:

image.png

于是我开始 debug,最终确认和上面的 demo 完全等价于下面的 demo。

image.png

所以大家直接运行上面的 demo 就能复现问题,JVM 参数如下:

-Xmx300M -Xms300M -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintReferenceGC

对了,运行平台是 JDK 8,JDK 6 是不存在这个问题的,因为 invokedynamic 指令以及 nashorn 是在 JDK 6 里不存在的。

上面的 demo 看起来是不是没毛病,但是却真的会让你的 GC 越来越慢,通过对 JVM 进行 debug 的方式抓出了下面的类似堆栈。

在 JDK 层面的栈如下:

image.png

最上面的 resolve 方法是一个 native 方法,这个方法发现可以直接调用到上面提到的 JNIHandles::make_weak_global 方法。

image.png

JNIHandles::make_weak_global 方法其实就是创建了一个 JNI Weak Reference。

在这里我要稍微描述下了,因为太繁琐就不准备贴代码了。

JVM 里有个数据结构叫做 JNIHandleBlock,之前提到了 global_handles 和 _weak_global_handles,其实他们都是一个 JNIHandleBlock 链表。

可以想象下里面有个 next 字段链到下一个 JNIHandleBlock,同时里面还有一个数组 _handle[],长度是 32,当我们要分配一个 JNI Weak Reference 的时候,就相当于在这个 JNIHandleBlock 链表里找一个空闲的位置(就是那些 _handle 数组),如果发现每个 JNIHandleBlock 的 _handle 数组都满了,就会创建一个新的 JNIHandleBlock,然后加到链里,注意这个链可以无限长,所以问题就来了,假如我们上层代码不断触发底层调用 JNIHandles::make_weak_global 来创建一个 JNI Weak Reference,那是不是意味着这个 JNIHandleBlock 链会不断增长,那会不会无穷增长呢,答案是肯定的,既然有创建 JNI Weak Reference 的 API,是不是也存在销毁 JNI Weak Reference 的 API?

当然是存在的,可以看到有 JNIHandles::destroy_weak_global 方法,这个实现其实很简单,就是相当于设计一个标记,表示这个数组里的这个位置是可以重用的了,在 GC 发生的时候,如果发现这个坑被标记了,于是就将这个坑加入到一个 free_list 里,当我们下面再想要分配一个 JNI Weak Reference 的时候,就可以有机会从 free_list 里去分配一个重用了。

但是这个 api 是在什么情况下才能调用的呢,其实只有在类卸载的时候才会去调用这个 api,那到底是什么类被卸载了,那就是调用了 MethodHandles.lookup() 这个方法的那个类,从我们上面的 demo 来看,就是 MHTest 这个主类本身,从同事给我的 demo 来看,其实是 jdk.nashorn.internal.runtime.Context 这个类,但是这个类其实是被 ext_classloader 加载的,也就是说这个类根本就不会被卸载,不能卸载那问题就严重了,意味着 GC 发生的时候并不能将那些引用对象已经死掉的坑置空,这样在我们需要再次分配 JNI Weak Reference 的时候,没有机会来重用那些坑,最终的结果就是不断地创建新的 JNIHandleBlock 加到链表里,导致链表越来越长,然而 GC 的时候是会去不断扫描这个链表的,因此看到 GC 的时候也会越来越长。

那还有一个问题,假如说调用 MethodHandles.lookup() 的类真的被卸载了还存在这个问题吗,答案是 GC 时间不会再恶化了,但是之前已经达到的恶化结果已经无法再修复了。

所以,这算是一个 JVM 设计上的缺陷吧,只要 Java 层面能触发不断调用到JNIHandles::make_weak_global,那这个问题将会立马重现。

其实解决方案我也想了一个,就是在遍历这些 JNIHandleBlock 的时候,如果发现对应的_handle数组全是空的话,那就直接将 JNIHandleBlock 回收掉,这样在 GC 发生的过程中并不会扫描到很多的 JNIHandleBlock 而耗时掉。

至于同事的那个问题的解决方案,其实也简单,对于同一个 JavaScript 脚本,不要每次都去调用 eval 方法,可以缓存起来,这样就减少了不断去触发调用 JNIHandles::make_weak_global 的动作从而可以避免 JNIHandleBlock 不断增长的问题。

文章转载自阿里云 MVP李嘉鹏,查看原文

相关实践学习
日志服务之使用Nginx模式采集日志
本文介绍如何通过日志服务控制台创建Nginx模式的Logtail配置快速采集Nginx日志并进行多维度分析。
目录
相关文章
|
5月前
|
Arthas 监控 Java
(十一)JVM成神路之性能调优篇:GC调优、Arthas工具详解及各场景下线上最佳配置推荐
“在当前的互联网开发模式下,系统访问量日涨、并发暴增、线上瓶颈等各种性能问题纷涌而至,性能优化成为了现时代开发过程中炙手可热的名词,无论是在开发、面试过程中,性能优化都是一个常谈常新的话题”。
491 3
|
2月前
|
缓存 算法 Java
JVM知识体系学习六:JVM垃圾是什么、GC常用垃圾清除算法、堆内存逻辑分区、栈上分配、对象何时进入老年代、有关老年代新生代的两个问题、常见的垃圾回收器、CMS
这篇文章详细介绍了Java虚拟机(JVM)中的垃圾回收机制,包括垃圾的定义、垃圾回收算法、堆内存的逻辑分区、对象的内存分配和回收过程,以及不同垃圾回收器的工作原理和参数设置。
73 4
JVM知识体系学习六:JVM垃圾是什么、GC常用垃圾清除算法、堆内存逻辑分区、栈上分配、对象何时进入老年代、有关老年代新生代的两个问题、常见的垃圾回收器、CMS
|
1月前
|
存储 监控 Java
JVM进阶调优系列(8)如何手把手,逐行教她看懂GC日志?| IT男的专属浪漫
本文介绍了如何通过JVM参数打印GC日志,并通过示例代码展示了频繁YGC和FGC的场景。文章首先讲解了常见的GC日志参数,如`-XX:+PrintGCDetails`、`-XX:+PrintGCDateStamps`等,然后通过具体的JVM参数和代码示例,模拟了不同内存分配情况下的GC行为。最后,详细解析了GC日志的内容,帮助读者理解GC的执行过程和GC处理机制。
|
2月前
|
Arthas 监控 Java
JVM知识体系学习七:了解JVM常用命令行参数、GC日志详解、调优三大方面(JVM规划和预调优、优化JVM环境、JVM运行出现的各种问题)、Arthas
这篇文章全面介绍了JVM的命令行参数、GC日志分析以及性能调优的各个方面,包括监控工具使用和实际案例分析。
59 3
|
2月前
|
算法 Java
JVM进阶调优系列(4)年轻代和老年代采用什么GC算法回收?
本文详细介绍了JVM中的GC算法,包括年轻代的复制算法和老年代的标记-整理算法。复制算法适用于年轻代,因其高效且能避免内存碎片;标记-整理算法则用于老年代,虽然效率较低,但能有效解决内存碎片问题。文章还解释了这两种算法的具体过程及其优缺点,并简要提及了其他GC算法。
 JVM进阶调优系列(4)年轻代和老年代采用什么GC算法回收?
|
2月前
|
存储 Java PHP
【JVM】垃圾回收机制(GC)之引用计数和可达性分析
【JVM】垃圾回收机制(GC)之引用计数和可达性分析
73 0
|
5月前
|
存储 算法 安全
(八)JVM成神路之GC分区篇:G1、ZGC、ShenandoahGC高性能收集器深入剖析
在《GC分代篇》中,我们曾对JVM中的分代GC收集器进行了全面阐述,而在本章中重点则是对JDK后续新版本中研发推出的高性能收集器进行深入剖析。
185 12
|
5月前
|
运维 Java Linux
(九)JVM成神路之性能调优、GC调试、各内存区、Linux参数大全及实用小技巧
本章节主要用于补齐之前GC篇章以及JVM运行时数据区的一些JVM参数,更多的作用也可以看作是JVM的参数列表大全。对于开发者而言,能够控制JVM的部分也就只有启动参数了,同时,对于JVM的性能调优而言,JVM的参数也是基础。
120 8
|
4月前
|
算法 Java 应用服务中间件
探索JVM垃圾回收算法:选择适合你应用的最佳GC策略
探索JVM垃圾回收算法:选择适合你应用的最佳GC策略
|
4月前
|
存储 监控 算法
深入解析JVM内部结构及GC机制的实战应用
深入解析JVM内部结构及GC机制的实战应用