百度360必应搜狗淘宝本站头条
当前位置:网站首页 > 编程字典 > 正文

Java YGC排查实战(java排查问题)

toyiye 2024-07-08 22:51 13 浏览 0 评论

现象:

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 太多:

  1. Springboot 2.4.1 版本bug,每次类加载都会new JarFileWrapper(不是本CASE的根因)
  2. 自定义的 feign SpringDecoder用法错误导致每次请求都会创建 HttpMessageConverts,进而导致不存在的类加载
  3. 没有复用http连接池导致每次请求创建socket

相关推荐

为何越来越多的编程语言使用JSON(为什么编程)

JSON是JavascriptObjectNotation的缩写,意思是Javascript对象表示法,是一种易于人类阅读和对编程友好的文本数据传递方法,是JavaScript语言规范定义的一个子...

何时在数据库中使用 JSON(数据库用json格式存储)

在本文中,您将了解何时应考虑将JSON数据类型添加到表中以及何时应避免使用它们。每天?分享?最新?软件?开发?,Devops,敏捷?,测试?以及?项目?管理?最新?,最热门?的?文章?,每天?花?...

MySQL 从零开始:05 数据类型(mysql数据类型有哪些,并举例)

前面的讲解中已经接触到了表的创建,表的创建是对字段的声明,比如:上述语句声明了字段的名称、类型、所占空间、默认值和是否可以为空等信息。其中的int、varchar、char和decimal都...

JSON对象花样进阶(json格式对象)

一、引言在现代Web开发中,JSON(JavaScriptObjectNotation)已经成为数据交换的标准格式。无论是从前端向后端发送数据,还是从后端接收数据,JSON都是不可或缺的一部分。...

深入理解 JSON 和 Form-data(json和formdata提交区别)

在讨论现代网络开发与API设计的语境下,理解客户端和服务器间如何有效且可靠地交换数据变得尤为关键。这里,特别值得关注的是两种主流数据格式:...

JSON 语法(json 语法 priority)

JSON语法是JavaScript语法的子集。JSON语法规则JSON语法是JavaScript对象表示法语法的子集。数据在名称/值对中数据由逗号分隔花括号保存对象方括号保存数组JS...

JSON语法详解(json的语法规则)

JSON语法规则JSON语法是JavaScript对象表示法语法的子集。数据在名称/值对中数据由逗号分隔大括号保存对象中括号保存数组注意:json的key是字符串,且必须是双引号,不能是单引号...

MySQL JSON数据类型操作(mysql的json)

概述mysql自5.7.8版本开始,就支持了json结构的数据存储和查询,这表明了mysql也在不断的学习和增加nosql数据库的有点。但mysql毕竟是关系型数据库,在处理json这种非结构化的数据...

JSON的数据模式(json数据格式示例)

像XML模式一样,JSON数据格式也有Schema,这是一个基于JSON格式的规范。JSON模式也以JSON格式编写。它用于验证JSON数据。JSON模式示例以下代码显示了基本的JSON模式。{"...

前端学习——JSON格式详解(后端json格式)

JSON(JavaScriptObjectNotation)是一种轻量级的数据交换格式。易于人阅读和编写。同时也易于机器解析和生成。它基于JavaScriptProgrammingLa...

什么是 JSON:详解 JSON 及其优势(什么叫json)

现在程序员还有谁不知道JSON吗?无论对于前端还是后端,JSON都是一种常见的数据格式。那么JSON到底是什么呢?JSON的定义...

PostgreSQL JSON 类型:处理结构化数据

PostgreSQL提供JSON类型,以存储结构化数据。JSON是一种开放的数据格式,可用于存储各种类型的值。什么是JSON类型?JSON类型表示JSON(JavaScriptO...

JavaScript:JSON、三种包装类(javascript 包)

JOSN:我们希望可以将一个对象在不同的语言中进行传递,以达到通信的目的,最佳方式就是将一个对象转换为字符串的形式JSON(JavaScriptObjectNotation)-JS的对象表示法...

Python数据分析 只要1分钟 教你玩转JSON 全程干货

Json简介:Json,全名JavaScriptObjectNotation,JSON(JavaScriptObjectNotation(记号、标记))是一种轻量级的数据交换格式。它基于J...

比较一下JSON与XML两种数据格式?(json和xml哪个好)

JSON(JavaScriptObjectNotation)和XML(eXtensibleMarkupLanguage)是在日常开发中比较常用的两种数据格式,它们主要的作用就是用来进行数据的传...

取消回复欢迎 发表评论:

请填写验证码