开启Dump文件自动转储

一般来说,线上运行的系统都会加上下面的 JVM 参数,以便如果线上出现 OOM 问题的时候,自动将事故现场保留下来。

1
2
#  当程序出现OutofMemory时,将会在相应的目录下生成一份dump文件,如果不指定选项HeapDumpPath则在当前目录下生成dump文件
-XX:+HeapDumpOnOutOfMemoryError -XX:ErrorFile=/logs/oom_dump/xxx.log -XX:HeapDumpPath=/logs/oom_dump/xxx.hprof

但是有某种情况下,pod会被k8s的某种保护机制下自动kill掉,那么dump文件没办法保存下来。此时也可以联系运维给这个服务加上EFS (Amazon 文件系统)等待下次出现能抓住这个问题。

EFS 是 Amazon 提供的完全托管的弹性网络文件系统,主要用于在 AWS 上运行的多台 EC2 实例之间 共享存储。它可以实现多个容器等实例同时挂载同一个 EFS 文件系统。

如果程序出现 OOM 之后,就是有代码存在内存泄漏的风险,这个时候即使能对外提供服务,其实也是有风险的,可能造成更多的请求有问题,所以该参数非常有必要,可以让 K8S 快速的再拉起来一个实例。

1
-XX:+ExitOnOutOfMemoryError

也有比较原始的方式获取到dump文件,通过 jmap 工具生成可以生成任意Java进程的dump文件

1
2
3
4
5
# 先找到PID
ps -ef | grep java

# jmap 转存快照
jmap -dump:format=b,file=/opt/dump/test.dump {PID}

无法在生产环境上使用jstackjmap等命令直接查错的原因:

  1. 需要和 JVM 进程交互
    • jstack、jmap 等工具会通过 Attach API 去连接目标 Java 进程。
    • 连接过程中 JVM 可能会有短暂停顿,尤其是在生成 堆转储(heap dump) 时,会触发 STW(Stop-The-World)
  1. 堆转储会消耗大量资源
    • jmap -dump 会把整个堆内存写到磁盘,如果堆是几十 GB,磁盘 IO 和 CPU 会瞬间飙升。
    • 在高并发的生产环境里,这可能导致应用延迟飙升,甚至直接 OOM / 崩溃。
  1. 阻塞风险
    • 某些 JVM bug 或特定版本下,jstack、jmap 执行时可能卡住,甚至把目标进程挂死。
    • 这在大规模线上系统中是 不可接受的风险

而使用-XX:+HeapDumpOnOutOfMemoryError这个参数,只在 JVM 已经抛出 OutOfMemoryError、进程无法继续正常工作时才触发 dump。HeapDumpOnOutOfMemoryError 的触发时刻,进程已经 内存耗尽,服务功能基本不可用,此时再做 dump 不会额外带来业务中断风险,反而能保留关键现场用于问题分析。

从安全性维度上讲,运维不会允许研发随时在生产上执行 jmap,因为这是“人为操作”,风险可控但不可预测。而使用JVM 参数 -XX:+HeapDumpOnOutOfMemoryError 是 只读配置,行为固定、无人工干预,且只在最坏情况下触发,可控且可预期

MAT工具参数调整

MAT需要JDK11才能运行

解决办法是,打开MAT的安装目录,有一个配置文件MemoryAnalyzer.ini。打开这个文件,在文件中指定JDK版本即可。新增两行配置:

1
-vm D:/jdkPath/bin/javaw.exe

在使用jvisualvm分析大的dump文件时,堆查器使用的内存不足

修改JAVA_HOME/lib/visualvm/etc/visualvm.conf文件中 visualvm_default_options=”-J-client -J-Xms24 -J-Xmx256m”,然后重启jvisualVM即可

MAT修改内存空间

分析堆转储文件需要消耗很多的堆空间,为了保证分析的效率和性能,在有条件的情况下,建议分配给 MAT 尽可能多的内存资源。两种方式分配内存资源给 MAT:
1)修改启动参数 MemoryAnalyzer.exe -vmargs -Xmx4g
2)编辑文件 MemoryAnalyzer.ini 添加 -vmargs – Xmx4g

案例一:查询条件未做限制全表扫描

现象

线上某个服务有接口非常慢,通过监控链路查看发现,中间的 GAP 时间非常大,实际接口并没有消耗很多时间,并且在那段时间里有很多这样的请求。

null

原因分析

先从监控链路分析了一波,发现请求是已经打到服务上了,处理之前不知道为什么等了 3s,猜测是不是机器当时负载太大了,通过 QPS 监控查看发现,在接口慢的时候 CPU 突然增高,同时也频繁的 GC ,并且时间很长,但是请求量并不大,并且这台机器很快就因为 Heap满了而被下掉了。

null

dump 出来的文件足有 4.8G,话不多说祭出 jvisualvm 进行分析,分析工具都被这个dump文件给搞挂了也报了个java.lang.OutOfMemoryError: Java heap space,加载成功之后就给出了导致OOM的线程。

找到class按照大小排序,占用最多的是一个 byte 数组,有 1.07G,char 数组也有1.03G,byte 数组都是数字,直接查看 char 数组吧,点进去查看具体内容,果然是那条count语句,一条 SQL 1.03G 难以想象。。。

null

null

这个userId的数据完全是外部传过来的,并没有做什么操作,从监控上看,这个入参有 64M,马上联系对应系统排查为啥会传这么多用户过来查询,经过一番排查确认他们有个bug,会把所有用户都发过来查询。。。到此问题排查清楚。

解决方案

对方系统控制传入userId的数量,我们自己的系统也对userId做一个限制,问题排查过程比较困难,修改方案总是那么的简单。

对于 SQL 语句,如果监测到没有where条件的全表查询应该默认增加一个合适的limit作为限制,防止这种问题拖垮整个系统。

案例二:文件删除导致内存泄漏

背景

今天下午,正酣畅淋漓的搬砖,突然运维同事在群里通知,核心服务某个节点内存异常,服务假死。神经一下子紧张起来,赶紧跑到运维那边观察现象。

观察的结果是服务内存溢出,该服务是核心服务,分配了5G内存。运维在转存快照后,立刻重启服务后正常。在接下来的一段时间里,另一台服务节点也发生了同样的情况。

分析过程

进入到Dominator Tree视图, 列出当前存活的对象的内存大小,这看起来像是我需要关注的重点。然后查了下这个类 java.io.DeleteOnExitHook 与 内存泄露的相关问题。

null

在删除文件使用 File.deleteOnExit() 方法时,并不是立刻删除文件,而是将该文件路径维护在类DeleteOnExit的一个LinkedHashSet中,最后在JVM关闭的时候,才会去删除这里面的文件,这个方法不能用于长时间运行的服务。

结论

问题定位于File.deleteOnExit()方法的调用,导致内存泄漏。调用该方法只会将需要删除文件的路径,维护在类DeleteOnExit的一个LinkedHashSet中,在JVM关闭时,才会去真正执行删除文件操作。这样导致DeleteOnExitHook这个对象越来越大,最终内存溢出。

File.delete()File.deleteOnExit() 的区别:
当调用delete()方法时,直接删除文件,不管该文件是否存在,一经调用立即执行
当调用deleteOnExit()方法时,只是相当于对deleteOnExit()作一个声明,当程序运行结束,JVM终止时才真正调用deleteOnExit()方法实现删除操作。

我写了下面这个测试方法,对比 delete()deleteOnExit()的区别,现象会比较明显。使用deleteOnExit时是在文件全部创建,JVM关闭的时候,才一个个删除文件,delete会立刻删除文件。(所以这个方法的使用场景是怎样的,我就不太清楚了)

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
public static void loopTest() throws IOException {
String root = "D:\\C_Temp\\files\\";

File path = new File(root);
if (!path.exists()) {
path.mkdirs();
}
int i = 0;
while (i < 40000) {
File file = new File(path, "Hello-" + i + ".txt");
file.createNewFile();
file.delete();
// file.deleteOnExit();
i++;
}
}

案例三:JVM启动参数有误

事故背景

2023年3月10日14时19分,C公司开发人员向A公司开发人员反映某开放接口从2023年3月10日14时许开始无法访问和使用。该系统为某基础数据接口服务,基于 HTTP 协议进行通信。按照惯例,首先排查网络是否异常,经运维人员检查,证明网络连通性没有问题。A公司开发组于2023年3月10日14时30分通知运维人员重启应用服务,期间短暂恢复正常。但是,很快,十分钟后,电话再次响起,告知服务又出现异常,无法访问。为了避免影响进一步扩大,A公司决定将程序紧急回滚至上一稳定版本。回滚后,系统业务功能恢复正常。短暂松一口气后,开始排查问题。

事故分析

根据前面的故障现象,初步猜测是内存问题。堆转储文件出来后,用*MAT(Memory Analyzer Tool)*工具打开转储文件,原以为会发现某个类型对象占用大量的内存,结果出乎意料,Histogram(直方图)中显示活跃对象居然只有100多M!尝试 Calculate Precise Retained Size(计算精确大小),计算结果与前面相差不大。检查 Outgoing References (追踪引用对象)和 Incoming References(追踪被引用对象)也未见明显异常,令人头大。

日志已经明确提示我们java.lang.OutOfMemoryError: Java heap space,首先肯定这是一个堆内存空间引起的问题,可能的原因有:

  • 内存加载数据量过大例如不受行数限制的数据库查询语句,或者不限制字节数的文件读取等,事故系统显然没有这些情况;

  • 内存泄漏(资源未关闭/无法回收)当系统存在大量未关闭的 IO 资源,或者错误使用ThreadLocal等场景时也会发生OOM,经排查,也不存在这种情况;

  • 系统内存不足系统内存不足以支撑当前业务场景所需要的内存,过小的机器内存或者不合理的JVM内存参数。

如果排除所有合理选项,最不合理那个会不会就是答案呢?遂开始检查机器的内存,根据运维的说法,机器内存为16GB,top命令查看java进程占用内存约为7.8GB,看起来似乎没毛病。

但是随后另一个同事注意到了一个事情,最后一次系统升级的时候,改动过应用启停脚本,对比旧版本的脚本,发现差异部分就是内存参数:

旧版本原为:

1
-Xms8g -Xmx8g -Xmn3g

新版本改为:

1
-Xms8g -Xmx8g -Xmn8g

事故原因

-Xms:初始堆大小,通常和 -Xmx 设置一样大,避免堆在运行中动态扩容,减少 GC 和内存分配的开销。

-Xmx:最大堆大小,和物理机/容器内存要匹配,不能随意大于系统可用内存

-Xmn:年轻代大小,年轻代太大,意味着老年代空间变小,Full GC 更容易触发;但太小的话 Minor GC 会频繁发生。

为什么-Xmn参数设置成与-Xmx参数一样的大小会导致OOM呢?该项目使用的JDK版本为1.8,看看JDK 8的内存模型:

null

不难发现,Heap Space Size = Young Space Size + Old Space Size,而-Xmn参数控制的正是 Young 区的大小,当堆区被 Young Gen 完全挤占,又有对象想要升代到 Old Gen 时,发现 Old 区空间不足,于是触发 Full GC,触发 Full GC 以后呢,通常又会面临两种情况:

  • Young 区又刚好腾出来一点空间,对象又不用放到 Old 区里面了,皆大欢喜

  • Young 区空间还是不够,对象还是得放到 Old 区,Old 区空间不够,卒,喜提OOM

  • 诶,就是奔着 Old 区去的,管你 Young 不 Young,Old 区空间不够,卒,喜提OOM

这个就解释了为什么系统刚刚启动时,会有一个短时间正常工作的现象,随后,当某段程序触发 Old Gen 升代时,就会发生随机的OOM错误。那么什么时候对象会进入老年代呢?这里也很有意思,不妨结合日志里面出现OOM的地方,对号入座:

  • 经历足够多次数 GC 依然存活的对象

  • 申请一个大对象(比如超过 Eden 区一半大小)

  • GC 后 Eden 区对象大小超过 S 区之和

  • Eden 区 + S0 区 GC 后,S1 区放不下

换言之,正常情况下,-Xmn参数总是应当小于-Xmx参数,否则就会触发OOM错误。触发 GC 的前后,Old 区几乎都没有空间,仅有的一点点还是JDK强行分配的(在启动JVM时强制覆写了我们的-Xmn参数)

事故复盘

这是一场典型的”人祸“,来源于某个同事的”调优“,比起追究责任,更重要的是带给我们的启发:

  • 即使是应用启停脚本,也应该作为程序的一部分,纳入测试验证流程和上线检查清单,禁止随意变更;

  • 很多时候,默认的就是最好的,矫枉则常常过正。

事故影响

造成C公司关键业务停摆半小时,生产系统紧急回滚一次。A公司相关负责人连夜编写事故报告一份。

案例四:YGC耗时过长

事故背景

今年4月份,我们的广告服务在新版本上线后,收到了大量的服务超时告警,通过下面的监控图可以看到:超时量突然大面积增加,1分钟内甚至达到了上千次接口超时。下面详细介绍下该问题的排查过程。

null

事故分析

检查监控

收到告警后,我们第一时间查看了监控系统,立马发现了YoungGC耗时过长的异常。我们的程序大概在21点50左右上线,通过下图可以看出:在上线之前,YGC基本几十毫秒内完成,而上线后YGC耗时明显变长,最长甚至达到了3秒多。

null

由于YGC期间程序会Stop The World,而我们上游系统设置的服务超时时间都在几百毫秒,因此推断:是因为YGC耗时过长引发了服务大面积超时。
按照GC问题的常规排查流程,我们立刻摘掉了一个节点,然后通过以下命令dump了堆内存文件用来保留现场。
jmap -dump:format=b,file=heap pid
最后对线上服务做了回滚处理,回滚后服务立马恢复了正常,接下来就是长达1天的问题排查和修复过程。

确认JVM配置

用下面的命令,我们再次检查了JVM的参数

1
2
3
4
5
6
7
ps aux | grep "applicationName=adsearch"
-Xms4g -Xmx4g -Xmn2g -Xss1024K
-XX:ParallelGCThreads=5
-XX:+UseConcMarkSweepGC
-XX:+UseParNewGC
-XX:+UseCMSCompactAtFullCollection
-XX:CMSInitiatingOccupancyFraction=80

可以看到堆内存为4G,新生代和老年代均为2G,新生代采用ParNew收集器。
再通过命令 jmap -heap pid 查到:新生代的Eden区为1.6G,S0和S1区均为0.2G。
本次上线并未修改JVM相关的任何参数,同时我们服务的请求量基本和往常持平。因此猜测:此问题大概率和上线的代码相关。

检查代码

再回到YGC的原理来思考这个问题,一次YGC的过程主要包括以下两个步骤:

1、从GC Root扫描对象,对存活对象进行标注
2、将存活对象复制到S1区或者晋升到Old区

根据下面的监控图可以看出:正常情况下,Survivor区的使用率一直维持在很低的水平(大概30M左右),但是上线后,Survivor区的使用率开始波动,最多的时候快占满0.2G了。而且,YGC耗时和Survivor区的使用率基本成正相关。因此,我们推测:应该是长生命周期的对象越来越多,导致标注和复制过程的耗时增加。

null

再回到服务的整体表现:上游流量并没有出现明显变化,正常情况下,核心接口的响应时间也基本在200ms以内,YGC的频率大概每8秒进行1次。

很显然,对于局部变量来说,在每次YGC后就能够马上被回收了。那为什么还会有如此多的对象在YGC后存活下来呢?

我们进一步将怀疑对象锁定在:程序的全局变量或者类静态变量上。但是diff了本次上线的代码,我们并未发现代码中有引入此类变量。

对dump的堆内存文件进行分析

代码排查没有进展后,我们开始从堆内存文件中寻找线索,使用MAT工具导入了第1步dump出来的堆文件后,然后通过Dominator Tree视图查看到了当前堆中的所有大对象。

null

立马发现NewOldMappingService这个类所占的空间很大,通过代码定位到:这个类位于第三方的client包中,由我们公司的商品团队提供,用于实现新旧类目转换(最近商品团队在对类目体系进行改造,为了兼容旧业务,需要进行新旧类目映射)。

进一步查看代码,发现这个类中存在大量的静态HashMap,用于缓存新旧类目转换时需要用到的各种数据,以减少RPC调用,提高转换性能。

null

原本以为,非常接近问题的真相了,但是深入排查发现:这个类的所有静态变量全部在类加载时就初始化完数据了,虽然会占到100多M的内存,但是之后基本不会再新增数据。并且,这个类早在3月份就上线使用了,client包的版本也一直没变过。

经过上面种种分析,这个类的静态HashMap会一直存活,经过多轮YGC后,最终晋升到老年代中,它不应该是YGC持续耗时过长的原因。因此,我们暂时排除了这个可疑点。

分析YGC处理Reference的耗时

团队对于YGC问题的排查经验很少,不知道再往下该如何分析了。基本扫光了网上可查到的所有案例,发现原因集中在这两类上:

1、对存活对象标注时间过长:比如重载了Object类的Finalize方法,导致标注Final Reference耗时过长;或者String.intern方法使用不当,导致YGC扫描StringTable时间过长。
2、长周期对象积累过多:比如本地缓存使用不当,积累了太多存活对象;或者锁竞争严重导致线程阻塞,局部变量的生命周期变长。

针对第1类问题,可以通过以下参数显示GC处理Reference的耗时-XX:+PrintReferenceGC。添加此参数后,可以看到不同类型的 reference 处理耗时都很短,因此又排除了此项因素。

null

再回到长周期对象进行分析

再往后,我们添加了各种GC参数试图寻找线索都没有结果,似乎要黔驴技穷,没有思路了。综合监控和种种分析来看:应该只有长周期对象才会引发我们这个问题。
折腾了好几个小时,最终峰回路转,一个小伙伴重新从MAT堆内存中找到了第二个怀疑点。

null

从上面的截图可以看到:大对象中排在第3位的ConfigService类进入了我们的视野,该类的一个ArrayList变量中竟然包含了270W个对象,而且大部分都是相同的元素。
ConfigService这个类在第三方Apollo的包中,不过源代码被公司架构部进行了二次改造,通过代码可以看出:问题出在了第11行,每次调用getConfig方法时都会往List中添加元素,并且未做去重处理

null

我们的广告服务在apollo中存储了大量的广告策略配置,而且大部分请求都会调用ConfigService的getConfig方法来获取配置,因此会不断地往静态变量namespaces中添加新对象,从而引发此问题。

至此,整个问题终于水落石出了。这个BUG是因为架构部在对apollo client包进行定制化开发时不小心引入的,很显然没有经过仔细测试,并且刚好在我们上线前一天发布到了中央仓库中,而公司基础组件库的版本是通过super-pom方式统一维护的,业务无感知。

解决方案

为了快速验证YGC耗时过长是因为此问题导致的,我们在一台服务器上直接用旧版本的apollo client 包进行了替换,然后重启了服务,观察了将近20分钟,YGC恢复正常。
最后,我们通知架构部修复BUG,重新发布了super-pom,彻底解决了这个问题。
通过上面这个案例,可以看到YGC问题其实比较难排查。相比FGC或者OOM,YGC的日志很简单,只知道新生代内存的变化和耗时,同时dump出来的堆内存必须要仔细排查才行。

另外,如果不清楚YGC的流程,排查起来会更加困难。这里,我对YGC相关的知识点再做下梳理,方便大家更全面的理解YGC。

YGC的相关知识点总结

5个问题重新认识新生代

null

YGC 在新生代中进行,首先要清楚新生代的堆结构划分。新生代分为Eden区和两个Survivor区,其中Eden:from:to = 8:1:1 (比例可以通过参数 –XX:SurvivorRatio 来设定 ),这是最基本的认识。

为什么会有新生代?

如果不分代,所有对象全部在一个区域,每次GC都需要对全堆进行扫描,存在效率问题。分代后,可分别控制回收频率,并采用不同的回收算法,确保GC性能全局最优。

为什么新生代会采用复制算法?

新生代的对象朝生夕死,大约90%的新建对象可以被很快回收,复制算法成本低,同时还能保证空间没有碎片。虽然标记整理算法也可以保证没有碎片,但是由于新生代要清理的对象数量很大,将存活的对象整理到待清理对象之前,需要大量的移动操作,时间复杂度比复制算法高。

为什么新生代需要两个Survivor区?

为了节省空间考虑,如果采用传统的复制算法,只有一个Survivor区,则Survivor区大小需要等于Eden区大小,此时空间消耗是8 * 2,而两块Survivor可以保持新对象始终在Eden区创建,存活对象在Survivor之间转移即可,空间消耗是8+1+1,明显后者的空间利用率更高。

新生代的实际可用空间是多少?

YGC后,总有一块Survivor区是空闲的,因此新生代的可用内存空间是90%。在YGC的log中或者通过 jmap -heap pid 命令查看新生代的空间时,如果发现capacity只有90%,不要觉得奇怪。

Eden区是如何加速内存分配的?

HotSpot虚拟机使用了两种技术来加快内存分配。分别是bump-the-pointer和TLAB(Thread Local Allocation Buffers)。

由于Eden区是连续的,因此bump-the-pointer在对象创建时,只需要检查最后一个对象后面是否有足够的内存即可,从而加快内存分配速度。

TLAB技术是对于多线程而言的,基于 CAS 的独享线程(Mutator Threads)可以优先将对象分配在 Eden 中的一块内存,因为是 Java 线程独享的内存区没有锁竞争,所以分配速度更快,每个 TLAB 都是一个线程独享的。

新生代的4种回收器

null

SerialGC(串行回收器),最古老的一种,单线程执行,适合单CPU场景。

ParNew(并行回收器),将串行回收器多线程化,适合多CPU场景,需要搭配老年代CMS回收器一起使用。

ParallelGC(并行回收器),和ParNew不同点在于它关注吞吐量,可设置期望的停顿时间,它在工作时会自动调整堆大小和其他参数。

G1(Garage-First回收器),JDK 9及以后版本的默认回收器,兼顾新生代和老年代,将堆拆成一系列Region,不要求内存块连续,新生代仍然是并行收集。

上述回收器均采用复制算法,都是独占式的,执行期间都会Stop The World.

YGC的触发时机

当Eden区空间不足时,就会触发YGC。结合新生代对象的内存分配看下详细过程:

1、新对象会先尝试在栈上分配,如果不行则尝试在TLAB分配,否则再看是否满足大对象条件要在老年代分配,最后才考虑在Eden区申请空间。

2、如果Eden区没有合适的空间,则触发YGC。

3、YGC时,对Eden区和From Survivor区的存活对象进行处理,如果满足动态年龄判断的条件或者To Survivor区空间不够则直接进入老年代,如果老年代空间也不够了,则会发生promotion failed,触发老年代的回收。否则将存活对象复制到To Survivor区。

4、此时Eden区和From Survivor区的剩余对象均为垃圾对象,可直接抹掉回收。

此外,老年代如果采用的是CMS回收器,为了减少CMS Remark阶段的耗时,也有可能会触发一次YGC,这里不作展开。

YGC的执行过程

YGC采用的复制算法,主要分成以下两个步骤:

1、查找GC Roots,将其引用的对象拷贝到S1区
2、递归遍历第1步的对象,拷贝其引用的对象到S1区或者晋升到Old区

上述整个过程都是需要暂停业务线程的(STW),不过ParNew等新生代回收器可以多线程并行执行,提高处理效率。
YGC通过可达性分析算法,从GC Root(可达对象的起点)开始向下搜索,标记出当前存活的对象,那么剩下未被标记的对象就是需要回收的对象。

null

可作为YGC时GC Root的对象包括以下几种:

1、虚拟机栈中引用的对象
2、方法区中静态属性、常量引用的对象
3、本地方法栈中引用的对象
4、被Synchronized锁持有的对象
5、记录当前被加载类的SystemDictionary
6、记录字符串常量引用的StringTable
7、存在跨代引用的对象
8、和GC Root处于同一CardTable的对象

其中1-3是大家容易想到的,而4-8很容易被忽视,却极有可能是分析YGC问题时的线索入口。

另外需要注意的是,针对下图中跨代引用的情况,老年代的对象A也必须作为GC Root的一部分,但是如果每次YGC时都去扫描老年代,肯定存在效率问题。在HotSpot JVM,引入卡表(Card Table)来对跨代引用的标记进行加速。

null

Card Table,简单理解是一种空间换时间的思路,因为存在跨代引用的对象大概占比不到1%,因此可将堆空间划分成大小为512字节的卡页,如果卡页中有一个对象存在跨代引用,则可以用1个字节来标识该卡页是dirty状态,卡页状态进一步通过写屏障技术进行维护。

遍历完GC Roots后,便能够找出第一批存活的对象,然后将其拷贝到S1区。接下来,就是一个递归查找和拷贝存活对象的过程。

S1区为了方便维护内存区域,引入了两个指针变量:_saved_mark_word和_top,其中_saved_mark_word表示当前遍历对象的位置,_top表示当前可分配内存的位置,很显然,_saved_mark_word到_top之间的对象都是已拷贝但未扫描的对象。

null

贝到S1区,_top也会往前移动,直到_saved_mark_word追上_top,说明S1区所有对象都已经遍历完成。

有一个细节点需要注意的是:拷贝对象的目标空间不一定是S1区,也可能是老年代。如果一个对象的年龄(经历的YGC次数)满足动态年龄判定条件便直接晋升到老年代中。对象的年龄保存在Java对象头的mark word数据结构中(如果大家对Java并发锁熟悉,肯定了解这个数据结构,不熟悉的建议查阅资料了解下,这里不做展开)。

最后的话

这篇文章通过线上案例分析并结合原理讲解,详细介绍了YGC的相关知识。从YGC实战角度出发,再简单总结一下:
1、首先要清楚YGC的执行原理,比如年轻代的堆内存结构、Eden区的内存分配机制、GC Roots扫描、对象拷贝过程等。
2、YGC的核心步骤是标注和复制,绝部分YGC问题都集中在这两步,因此可以结合YGC日志和堆内存变化情况逐一排查,同时dump的堆内存文件需要仔细分析。

案例五:动态对象年龄判定机制引起STW

问题描述

公司某规则引擎系统,在每次发版启动会手动预热,预热完成当流量切进来之后会偶发的出现一次长达1-2秒的Young GC(流量并不大,并且LB下的每个节点都会出现该情况)

在这次长暂停之后,每一次的年轻代GC暂停时间又都恢复在20-100ms以内

2秒虽然看起来不算长吧,但规则引擎每次执行也才几毫秒,这谁能忍?而且这玩意一旦超时,出单可能也跟着超时失败!

问题分析

在分析该系统GC日志后发现,2s暂停发生在Young GC阶段,而且每次发生长暂停的Young GC都会伴随着新生代对象的晋升(Promotion)

启动后第一次年轻代GC日志

1
2
3
4
5
6
2023-04-23T16:28:31.108+0800: [GC2023-04-23T16:28:31.108+0800: [ParNew2023-04-23T16:28:31.229+0800: [SoftReference, 0 refs, 0.0000950 secs]2023-04-23T16:28:31.229+0800: [WeakReference, 1156 refs, 0.0001040 secs]2023-04-23T16:28:31.229+0800: [FinalReference, 10410 refs, 0.0103720 secs]2023-04-23T16:28:31.240+0800: [PhantomReference, 286 refs, 2 refs, 0.0129420 secs]2023-04-23T16:28:31.253+0800: [JNI Weak Reference, 0.0000000 secs]
Desired survivor size 214728704 bytes, new threshold 1 (max 15)
- age 1: 315529928 bytes, 315529928 total
- age 2: 40956656 bytes, 356486584 total
- age 3: 8408040 bytes, 364894624 total
: 3544342K->374555K(3774912K), 0.1444710 secs] 3544342K->374555K(10066368K), 0.1446290 secs] [Times: user=1.46 sys=0.09, real=0.15 secs]

长暂停年轻代GC日志

1
2
3
4
2023-04-23T17:18:28.514+0800: [GC2023-04-23T17:18:28.514+0800: [ParNew2023-04-23T17:18:29.975+0800: [SoftReference, 0 refs, 0.0000660 secs]2023-04-23T17:18:29.975+0800: [WeakReference, 1224 refs, 0.0001400 secs]2023-04-23T17:18:29.975+0800: [FinalReference, 8898 refs, 0.0149670 secs]2023-04-23T17:18:29.990+0800: [PhantomReference, 600 refs, 1 refs, 0.0344300 secs]2023-04-23T17:18:30.025+0800: [JNI Weak Reference, 0.0000210 secs]
Desired survivor size 214728704 bytes, new threshold 15 (max 15)
- age 1: 79203576 bytes, 79203576 total
: 3730075K->304371K(3774912K), 1.5114000 secs] 3730075K->676858K(10066368K), 1.5114870 secs] [Times: user=6.32 sys=0.58, real=1.51 secs]

从这个长暂停的GC日志来看,是发生了晋升的,在Young GC后,有363M+的对象晋升到了老年代,这个晋升操作因该就是耗时原因(ps: 检查过safepoint原因,不存在异常)

由于日志参数中没有配置-XX:+PrintHeapAtGC参数,这里是手动计算的晋升大小:

1
2
年轻代年轻变化 - 全堆容量变化 = 晋升大小
(304371K - 3730075K) - (676858K - 3730075K) = 372487K(363M)

下一次年轻代GC日志

1
2
3
4
5
2023-04-23T17:23:39.749+0800: [GC2023-04-23T17:23:39.749+0800: [ParNew2023-04-23T17:23:39.774+0800: [SoftReference, 0 refs, 0.0000500 secs]2023-04-23T17:23:39.774+0800: [WeakReference, 3165 refs, 0.0002720 secs]2023-04-23T17:23:39.774+0800: [FinalReference, 3520 refs, 0.0021520 secs]2023-04-23T17:23:39.776+0800: [PhantomReference, 150 refs, 1 refs, 0.0051910 secs]2023-04-23T17:23:39.782+0800: [JNI Weak Reference, 0.0000100 secs]
Desired survivor size 214728704 bytes, new threshold 15 (max 15)
- age 1: 17076040 bytes, 17076040 total
- age 2: 40832336 bytes, 57908376 total
: 3659891K->90428K(3774912K), 0.0321300 secs] 4032378K->462914K(10066368K), 0.0322210 secs] [Times: user=0.30 sys=0.00, real=0.03 secs]

乍一看好像没什么问题,仔细想想还是发现了不对劲,为什么程序刚启动第二次gc就发生了晋升?

推测这里应该是动态年龄判定导致的,GC中晋升年龄阈值并不是固定的15,而是jvm每次gc后动态计算的

年轻代晋升机制

为了能更好地适应不同程序的内存状况,虚拟机并不是永远地要求对象的年龄必须达到了MaxTenuringThreshold才能晋升老年代,如果在Survivor空间中相同年龄所有对象大小的总和大于Survivor空间的一半,年龄大于或等于该年龄的对象就可以直接进入老年代,无须等到MaxTenuringThreshold中要求的年龄

《深入理解Java虚拟机》一书中提到,对象晋升年龄的阈值是动态判定的。

不过经查阅其他资料和验证后,发现此处和《深入理解Java虚拟机》解释的有些出入

其实就是按年龄给对象分组,取total(累加值,小于等与当前年龄的对象总大小)最大的年龄分组,如果该分组的total大于survivor的一半,就将晋升年龄阈值更新为该分组的年龄

注意:不是是超过survivor一半就晋升,超过survivor一半只会重新设置晋升阈值(threshold),在下一次GC才会使用该新阈值

从上面第一次的GC日志也可以证明这个结论,在这次GC中全堆的内存变化和年轻代内存变化是相等的,所以并没有发生对象的晋升

就像上面的日志中,第一次GC只是将threshold设置为1,因为此时survivor一半为214728704 bytes,而年龄为1的对象总和有315529928 bytes,超过了Desired survivor size,所以在本次GC后将threshold设置为年龄为1的对象年龄1

1
2
3
4
5
这里更新了对象晋升年龄阈值为1
Desired survivor size 214728704 bytes, new threshold 1 (max 15)
- age 1: 315529928 bytes, 315529928 total
- age 2: 40956656 bytes, 356486584 total
- age 3: 8408040 bytes, 364894624 total

这里顺便解释下这个年龄分布的输出内容:

1
- age   1:  315529928 bytes,  315529928 total 

- age 1表示年龄为1的对象分组,315529928 bytes表示年龄为1的对象占用内存大小

315529928 total这个是一个累加值,表示小于等于当前分组年龄的对象总大小。先把对象按年龄分组,age 1的分组total为age 1总大小(前面的xxx bytes),age 2的分组total为age 1 + age 2总大小,age n的分组total为age 1 + age 2 + ... +age n的总大小,累加规则如下图所示

null

当total最大的分组的total值超过了survivor/2时,就会更新晋升阈值

在第二次年轻代GC“长暂停年轻代GC日志”中,由于新的晋升年龄阈值为1,所以那些经历了一次GC并存活并且现在仍然可达(reachable)的对象们就会发生晋升了

由于此次GC发生了363M的对象晋升,所以导致了长暂停

思考

JVM中这个“动态对象年龄判定”真的合理吗?

个人认为机制是好的,可以更好的适应不同程序的内存状况,但不是任何场景都适合,比如在本文中这个刚启动不就GC的场景下就会有问题

因为在程序刚启动时,大多数对象年龄都是0或者1,很容易出现年龄为1的大量存活对象;在这个“动态对象年龄判定”机制下,就会导致新的晋升阈值被设置为1,导致这些不该晋升的对象发生了晋升

比如程序在初始化,正在加载各种资源时发生了Young GC,加载逻辑还在执行中,很多新建的对象年龄在这次GC时还是可达的(reachable)

经历了这次GC后,这些对象年龄更新为1,但是由于“动态对象年龄判定”机制的影响,晋升年龄阈值更新为了“最大的对象年龄分组”的年龄,也就是这批刚经历了一次GC的对象们

在这次GC之后不久,资源初始化完成了,涉及的相关对象有很可能不可达了,但是由于刚才晋升年龄阈值被更新为了1,在下一次正常的Young GC这批年龄为1的对象会直接发生晋升,提前或者说错误的发生了晋升

解决方案

经查阅文档、资料,发现“动态年龄判定”这个机制并不能禁用,所以如果想解决这个问题,只有靠“绕过”这个计算规则了

动态年龄的判定,是根据Survivor空间中相同年龄所有对象大小的总和大于Survivor空间的一半来判定的,那么根据这个机制解决也很简单

由于我们足够了解自己的系统,清楚的知道加载资源所需的大概内存,完全可以设定一个大于这些暂时可达的对象总和的数值来作为survivor的容量

比如上面的日志中,第一次GC后年龄为1的对象有315529928 Bytes(300M),Desired survivor size为(survivor size /2)214728704 bytes(204M),那么survivor就可以设置为600M以上。

不过为了稳妥,还是将survivor调到800M,这样desired survivor size就是400M左右,在第一次Young GC后,就不会因年龄为1的对象总和超过了desired survivor size而导致晋升年龄阈值的更新了,从而也就不会有提前/错误晋升而导致的GC长暂停问题

survivor不可以直接指定大小,不过可以通过-XX:SurvivorRatio这种调节比例的方式来调节survivor大小

1
-XX:SurvivorRatio=8

表示两个Survivor和Edgen区的比,8表示两个Survivor:Eden=2:8,即一个Survivor占新生代的1/10。

好了,现在直接通过比例,强行给 Survivor 调大

1
-XX:SurvivorRatio=3

调整之后,Survivor 总占比为 40%,大小为 1717829632 Bytes,单个 S0/S1的一半也有 10% - 429457408 Bytes,远超 age=1 的分组总大小 315529928 Bytes。

这样一来, Young GC 后复制到 Survivor 的对象(最大年龄分组)占总比例的大小就不会到 50% 了,也就不会把 MaxTenuringThreshold 更新为 1 ,自然就解决了这个“乱晋升”的问题

改完收工,再次发版手动预热后,再也没有切量后长暂停的问题了,Young GC稳定在 30-100ms,成功解决!