现象:
2024-03-18 收到GC耗时告警
从GC日志上看 2024-03-18 确实单次GC超时300ms,时间拉长了看,此服务 Ref Proc阶段耗时都较高,顺便查看了其他项目,发现大多数项目都存在同样的问题,是一个普遍存在的问题,因此大概判断问题可能出在中间件代码上。
排查:
(1)确定耗时阶段
因为是Ref Proc耗时高,增加 PrintReferenceGC参数后重新发布,查看到底是什么Ref耗时高?
从上图看出是FinalReference实例太多导致耗时高,FinalReference只有一个子类Finalizer,使用jmap -histo 1 | grep 'Finalizer' 持续观察Finalizer对象数量,当Finalizer对象数量再次达到3w时dump内存后查看Finalizer引用的对象到底是啥?
可以看到大部分是org.springframework.boot.loader.jar.JarFileWrapper对象,也就是因为JarFileWrapper太多导致FinalReference太多。
(2)JarFileWrapper为什么这么多?
google搜索“JarFileWrapper GC”关键词,发现 https://github.com/spring-projects/spring-boot/issues/28042 已经有人碰到相关问题,从讨论上看,高版本已经修复此问题,具体的修复commit是 https://github.com/spring-projects/spring-boot/commit/a93304c9736e5a94f35941f48882c82046ec0d46 ,我们当前使用的springboot是2.4.1,查看2.4.1的源代码发现没有此commit,仍然是每次new JarFileWrapper,从讨论中可以看到2.4.12已修复此问题,再次看看2.4.12版本,从下图可以看出确实已修复。
升级springboot版本后,2024-03-19 晚上灰度一台机器,2024-03-20 查看监控,发现gc耗时仍然很高(> 100ms),查看日志发现,仍然是Ref Proc耗时高,还是FinalReference太多,说明除了springboot的bug外还有其他原因导致FinalReference变多。
(3)继续确定FinalReference
要确定FinalReference到底引用的是什么需要dump内存,为了更准确的找到问题,我们需要找一个合适的dump内存的时机(这个时机就是当 FinalReference 对象“足够多”时)。
先观察 Finalizer 对象的趋势:通过在机器上频繁执行 jmap -histo 1 | grep 'Finalizer' 发现,Finalier实例数上涨的很快,基本上1s能上涨2k左右,最高能达到18w多。
从下面的GC日志上看,Finalizer实例在14w时耗时达到131ms,我们通过频繁执行 jmap -histo 1 | grep 'Finalizer' 观察Finalizer个数,在数量快达到14w的时候dump内存继续分析。
另外,为了确认升级springboot版本后的效果,特意在机器上多次分别统计 Finalizer 和 JarFileWrapper,发现两者数量一起增长,数量相近,所以大概率还是因为JarFileWrapper太多导致的FinalReference太多。
从下面的dump内存上看,JarFileWrapper数量达到119461个,Finalizer数量119883个,和 jmap 命令观察到的现象一致。
(4)跟踪JarFileWrapper
升级springboot版本后 JarFileWrapper仍然很多,为了搞清楚此对象为什么这么多,我们需要进一步确定 JarFileWrapper对象怎么来的。
JarFileWrapper类只有一个构造函数,要弄清楚JarFileWrapper为什么多,那么需要观察它的构造函数是怎么被调用的。利用arthas跟踪一下JarFileWrapper的构造函数调用堆栈,看看到底是什么场景在一直调用:
arthas命令:stack org.springframework.boot.loader.jar.JarFileWrapper <init>
arthas stack命令返回的都是如下的调用堆栈:
从梳理出来的几个核心类来看,每次产生http接口的feign调用时,都会导致ClassUtils
.forName被调用,进而导致JarFileWrapper构造函数被调用。
从下图的ClassUtils.isPresent实现来看,实际上就是调用ClassUtils.forName加载此类,不抛异常就返回true
也就是说每次业务接口调用都会最终调用到ClassUtils.forName,进而调用到JarFileWrapper.<init>,但是一个类只会被一个ClassLoader加载一次,不会导致JarFileWrapper一直创建,所以这里我们猜测可能是在加载一个不存在的类,因为当一个存在的类被加载一次后,后面无论调用多少次ClassUtils.forName都不会真正的进行类加载。
(5)确定不存在类
通过上面的分析,我们可以较容易的确定 ClassUtils.isPresent或者ClassUtils.forName函数调用时的参数就是我们想要找的不存在的类名。
先看下 ClassUtils.isPresent 方法的定义:
public static boolean isPresent(String className, @Nullable ClassLoader classLoader)
我们只需要跟踪ClassUtils.isPresent方法的参数即可,具体的arthas跟踪命令如下:
watch org.springframework.util.ClassUtils isPresent '{params[0], returnObj}'
结果如下,可以看到方法第一个参数className=org.joda.time.YearMonth,返回值为false。
(6)什么要加载不存在的类?
已经确定了是因为 org.joda.time.YearMonth 类不存在导致,我们看看为什么要加载这个类?还是回到上面的调用堆栈进行分析。
这里需要仔细的分析调用堆栈,重点看业务代码附近的调用(为什么?因为开源框架大概率没有如此明显的bug,很可能是我们自己写的代码有问题),梳理一下调用堆栈:
SpringDecoder.decode()
-> FeignConfig.lambda$feignDecoder$1
-> HttpMessageConverters.<init>
-> ClassUtils.isPresent
其中 FeignConfig.lambda$feignDecoder$1 是业务代码,从堆栈上看是因为我们代码调用HttpMessageConverters.<init>,最终导致加载不存在的 org.joda.time.YearMonth。
我们先看看HttpMessageConverters.<init>函数调用的逻辑(跟着源码结合最开始的堆栈记录看),这里只给出流程中几个重要的截图。
到这里我们知道了为什么要加载org.joda.time.YearMonth这个不存在的类,因为是spring框架里写死的一段逻辑,那么为什么要一直加载呢?
再次回到我们梳理的调用堆栈(下图),要搞清楚为什么一直加载,需要弄清楚SpringDecoder.decode()和FeignConfig.lambda$feignDecoder$1的逻辑。
从上面的源码可以看出,每次 SpringDecoder.decode() 调用时都会调用 messageConverters.getObject() ,messageConverters是一个 ObjectFactory 类型,通过构造函数传入,而我们传入的是一个lamda表达式:
() -> new HttpMessageConverters(messageConverters.getObject().getConverters()))
也就是说每次请求都会调用 new HttpMessageConverters(),最终导致org.joda.time.YearMonth这个不存在的类加载,因此导致 JarFileWrapper 越来越多。
(7)第二次修复
从上面的分析可以看出,每次请求都会调用这个 new HttpMessageConverters(messageConverters.getObject().getConverters()),实际上HttpMessageConverter在项目启动的时候已经固定了,没必要每次请求都去重新构建,因此我们重写这一块。
改成:
(8)第二次验证
2024-03-20 晚上灰度1台,2024-03-21日查看监控如下:
优化前后,GC Pause(Max) 指标有明显的改善,优化后基本在50ms以下。
为了确认Finalizer对象数量是否完全正常,登录两台启动时间差不多的机器查看Finalizer对象个数:
左图为灰度的机器,Finalizer对象6k左右,多次观察发现仍然在继续增长,右图为未优化机器,Finalizer对象在10w级别,上涨的很快。虽然优化后Finalizer对象有大幅降低,但是仍然是在小幅度上涨,并且达到6k多,应该还存在问题。
(9)继续确定Finalizer:
优化后,虽然GC耗时有大幅降低,但是仍然会发生较长时间的GC,随便找几个耗时超过50ms的日志看,基本现象都是FinalReference数量多(8k左右)耗时高,占整个GC耗时的 1/3 左右,说明FinalReference仍然存在问题,如果能降低此部分的耗时,整个GC耗时可以控制在30-40ms。
从GC日志看,FinalReference数量会达到9k,还是非常多,我们不停的监控FinalReference数量,在达到9k时dump内存分析。
用MAT分析dump文件,先看看Finalizer的referent到底是啥?使用如下OQL进行统计,导出结果成txt,再使用 sort | uniq -c 排序统计一下得到下面文本文件的结果:
OQL语句:
SELECT classof(f.referent).getName() AS name FROM java.lang.ref.Finalizer f WHERE (f.referent != null)
这里只分析referent不为null的Finalizer对象,因为 referent=null的Finalizer不会影响GC耗时
这里为什么不使用之前使用的 OQL:select f.referent from java.lang.ref.Finalizer f?因为referent为null的FinalReference对象的处理逻辑在Java代码层面(大家知道有一个 ReferenceHandler 线程吗?),不在JVM层面,所以对YGC的耗时无影响。
可以看到主要是 sun.security.ssl.SSLSocketImpl,java.net.SocksSocketImpl这两个类太多,随便找一个SocksSocketImpl对象看看outcome 引用,发现SSLSocketImpl类的socket字段引用了 SocksSocketImpl对象,这样也能解释上图中这两个类最多的现象。
接下来,我们继续看看 SSLSocketImpl到底是连接到哪里的socket?从java源码可以看到SSLSocketImpl.peerHost字段代表这个socket连接的对端的地址。
再次使用OQL统计下peerHost内容
select toString(s.peerHost) from sun.security.ssl.SSLSocketImpl s
从下图可以看出全部都是连接到 api.xx.srv 这个域名的socket,到这里我们可以猜测了,连接到这个域名的socket大概率没有得到复用,请求多了导致socket多。
从项目源代码中搜索到 api.xx.srv 这个域名只有一个地方在使用(如下图),场景是调用其他平台的一个http接口,从代码上可以看到每次调用时都重新构建了一个新的OkHttpClient,而OkHttpClient的源码注释一开始就强调了 OkHttpClient 对象需要共享,到这里问题基本上就定位了,因为我们没有重复利用 OkHttpClient,导致每次请求时都重新创建socket,导致socket对象太多,最后导致 FinalReference 对象太多。
(10)第三次验证:
2024-03-21 晚再次灰度1台机器,2024-03-22 查看监控如下:
从上图可以看出,最终 GC Max指标控制在50ms以下,GC Count指标也得到了改善。
结论:
本CASE均是由 GC的Ref Proc阶段高耗时引起,一共三种场景导致 FinalReference 太多:
- Springboot 2.4.1 版本bug,每次类加载都会new JarFileWrapper(不是本CASE的根因)
- 自定义的 feign SpringDecoder用法错误导致每次请求都会创建 HttpMessageConverts,进而导致不存在的类加载
- 没有复用http连接池导致每次请求创建socket