关于java:Spring-Boot-微服务性能下降九成使用-Arthas-定位根因

51次阅读

共计 10666 个字符,预计需要花费 27 分钟才能阅读完成。

作者 | 王瑞显  掌门教育基础架构部研发工程师
起源 | 阿里巴巴云原生公众号

背景

接管到公司业务部门的开发反馈,利用在降级公司外部框架后,UAT(预生产)环境接口性能压测不达标。
降级前压测报告:

降级后压测报告:

在机器配置(1C4G)雷同的状况下,吞吐量从原来的 53.9/s 降落到了 6.4/s,且 CPU 负载较高。

并且开发反馈从公司全链路监控零碎 SkyWalking 中查问到的链路信息能够得悉大部分申请 Feign 调用的耗时不太失常(390ms),而理论被调用的上游服务响应速度很快(3ms)。

定位问题

在接管到反馈当前,我立刻申请了相应机器的权限,并往相应机器上传了 Arthas(version 3.4.3)。

让业务方放弃压测,开始问题定位。

1. 执行 profiler 命令对 CPU 进行性能剖析

[arthas@17962]$ profiler start -d 30 -f /tmp/arthas/1.txt

期待 30s 后,关上 1.txt,查看 CPU 性能剖析后果,结尾局部示例如下:

--- 1630160766 ns (4.24%), 141 samples
  ......
  [14] org.springframework.boot.loader.LaunchedURLClassLoader.definePackageIfNecessary
  [15] org.springframework.boot.loader.LaunchedURLClassLoader.loadClass
  [16] java.lang.ClassLoader.loadClass
  [17] java.lang.Class.forName0
  [18] java.lang.Class.forName
  [19] org.springframework.util.ClassUtils.forName
  [20] org.springframework.http.converter.json.Jackson2ObjectMapperBuilder.registerWellKnownModulesIfAvailable
  [21] org.springframework.http.converter.json.Jackson2ObjectMapperBuilder.configure
  [22] org.springframework.http.converter.json.Jackson2ObjectMapperBuilder.build
  [23] org.springframework.web.servlet.config.annotation.WebMvcConfigurationSupport.addDefaultHttpMessageConverters
  [24] org.springframework.web.servlet.config.annotation.WebMvcConfigurationSupport.getMessageConverters
  [25] org.springframework.boot.autoconfigure.http.HttpMessageConverters$1.defaultMessageConverters
  [26] org.springframework.boot.autoconfigure.http.HttpMessageConverters.getDefaultConverters
  [27] org.springframework.boot.autoconfigure.http.HttpMessageConverters.<init>
  [28] org.springframework.boot.autoconfigure.http.HttpMessageConverters.<init>
  [29] org.springframework.boot.autoconfigure.http.HttpMessageConverters.<init>
  [30] com.zhangmen.xxx.DefaultFeignConfig.lambda$feignDecoder$0
  [31] com.zhangmen.xxx.DefaultFeignConfig$$Lambda$704.256909008.getObject
  [32] org.springframework.cloud.openfeign.support.SpringDecoder.decode
  [33] org.springframework.cloud.openfeign.support.ResponseEntityDecoder.decode
 ......

2. 对可疑的办法执行 trace 命令输入办法门路上每个节点的耗时

剖析上一步失去的 CPU 性能剖析后果,能够发现最占用 CPU 的栈中,的确有 Feign 相干的栈帧。

并且发现 Feign 相干的栈帧四周呈现了 com.zhangmen 相干的栈帧:com.zhangmen.xxx.DefaultFeignConfig$$Lambda$704.256909008.getObject 和 com.zhangmen.xxx.DefaultFeignConfig.lambda$feignDecoder$0。

在 1.txt 中搜寻 com.zhangmen.xxx.DefaultFeignConfig,发现有 340 次命中,因而认为这是一个十分可疑的办法。

执行 trace 命令输入该办法门路上每个节点的耗时:

[arthas@17962]$ trace com.zhangmen.xxx.DefaultFeignConfig * '#cost>200' -n 3
`---[603.999323ms] com.zhangmen.xxx.DefaultFeignConfig:lambda$feignEncoder$1()
    `---[603.856565ms] org.springframework.boot.autoconfigure.http.HttpMessageConverters:<init>() #42

发现 org.springframework.boot.autoconfigure.http.HttpMessageConverters:<init>() 比拟耗时,并持续一层层 trace 追踪上来:

[arthas@17962]$ trace org.springframework.boot.autoconfigure.http.HttpMessageConverters <init> '#cost>200' -n 3
......
[arthas@17962]$ trace org.springframework.http.converter.json.Jackson2ObjectMapperBuilder registerWellKnownModulesIfAvailable '#cost>200' -n 3

最终发现 org.springframework.util.ClassUtils:forName() 比拟耗时,并且抛出了异样。

应用 watch 命令查看具体的异样:

[arthas@17962]$ watch org.springframework.util.ClassUtils forName -e "throwExp" -n 

解决问题

将定位到的问题,反馈给相干业务开发,并倡议引入 jackson-datatype-joda 依赖。

引入依赖后压测报告:

吞吐量从原来的 6.4/s 晋升到了 69.3/s,比降级框架前的 53.9/s 还要高。

这时候相干业务开发反馈,这个问题是代码中自定义了 Feign 的编解码器(下图所示)导致的,并且这个编解码器在降级框架前也是始终存在的。

于是,对降级框架前的代码进行压测并在压测过程中应用 Arthas 执行以下命令:

发现同样有这个异样。引入 jackson-datatype-joda 依赖,再次进行压测,压测报告如下:

汇总后面的压测后果:

能够发现一个新的问题:为什么新旧版本同时不引入依赖,吞吐量相差近 8 倍,新旧版本同时引入依赖,吞吐量相差近 1 倍?

进一步定位问题

依据上一步中发现的新问题,接下来对 未降级框架并引入依赖的版本 和 降级框架并引入依赖的版本 别离进行压测,并在压测过程中应用 Arthas 的 profiler 命令采样 CPU 性能剖析数据,失去样本 1 和样本 2。并从样本 1 和样本 2 中找到类似栈进行比照:

通过比照能够发现,两个样本的类似栈的前 17 行有所不同。并对样本 2 中的可疑栈帧进行 trace 追踪:

[arthas@10561]$ trace org.apache.catalina.loader.WebappClassLoaderBase$CombinedEnumeration * '#cost>100' -n 3
`---[171.744137ms] org.apache.catalina.loader.WebappClassLoaderBase$CombinedEnumeration:hasMoreElements()
    `---[171.736943ms] org.apache.catalina.loader.WebappClassLoaderBase$CombinedEnumeration:inc() #2685
        `---[171.724546ms] org.apache.catalina.loader.WebappClassLoaderBase$CombinedEnumeration:inc()

发现降级框架后,在类加载器这部分存在比拟耗时的状况。

而对样本 1 中这部分进行 trace 追踪没有呈现耗时大于 100ms 的状况。

又进一步应用 profiler 命令,别离生成两个版本在压测场景下的火焰图,并找到类似栈进行比照:

[arthas@10561]$ profiler start -d 30 -f /tmp/arthas/1.svg

发现 降级框架并引入依赖的版本 还多出了一些 org/springframework/boot/loader/ 相干的栈。

进一步解决问题

将新的发现反馈给相干业务开发。

他们反映此次除了框架降级外,还有 Spring Boot war to jar 部署的调整。从应用独立的 Tomcat war 部署,革新成用 Spring Boot 内嵌 Tomcat java -jar 部署。故狐疑两种部署形式在类加载器上存在性能差别。
相干业务开发在我上一步定位问题期间,依据我最后定位到的问题,在 Google 搜寻 feign com.fasterxml.jackson.datatype.joda.JodaModule,找到了一篇相干的文章《loadClass 导致线上服务卡顿剖析》。

文章中的作者,遇到的问题与咱们根本类似。

看了这篇文章后,我又 Debug 了局部源码,最初理解到问题产生的根本原因是:SpringEncoder / SpringDecoder 在每次编码 / 解码时都会调用 ObjectFactory<HttpMessageConverters>.getObject()).getConverters() 获取 HttpMessageConverters。而咱们自定义的 DefaultFeignConfig 中配置的 ObjectFactory<HttpMessageConverters> 的实现是每次都 new 一个新的 HttpMessageConverters 对象。

HttpMessageConverters 的构造方法又默认会执行 getDefaultConverters 办法获取默认的 HttpMessageConverter 汇合,并初始化这些默认的 HttpMessageConverter。其中的 MappingJackson2HttpMessageConverter(有两个,见下图)每次初始化时都会加载不在 classpath 中的 com.fasterxml.jackson.datatype.joda.JodaModule 和 com.fasterxml.jackson.datatype.joda$JodaModule(org.springframework.util.ClassUtils 加载不到类时,会尝试再加载一下外部类),并抛出 ClassNotFoundException,且该异样最初被生吞。

而局部和 XML 相干的默认的 HttpMessageConverter,SourceHttpMessageConverter 和 Jaxb2RootElementHttpMessageConverter(各有两个,见下图)每次初始化时,会执行 TransformerFactory.newInstance(),执行过程中会应用 SPI 扫描 classpath 下的 META-INF / services 目录获取具体的实现,并且每次扫描完也没有获取到具体的实现,最终应用默认指定的 com.sun.org.apache.xalan.internal.xsltc.trax.TransformerFactoryImpl 作为实现。

最终导致每一次 Feign 调用(蕴含编码和解码),都会加载 4 次不在 classpath 中的 com.fasterxml.jackson.datatype.joda.JodaModule 和 com.fasterxml.jackson.datatype.joda$JodaModule(共 8 次),且 8 次应用 SPI 扫描 classpath 下的 META-INF / services 目录获取查找不到的实现,而 war to jar 后,类加载器在频繁查找和加载资源上的性能有所降落,最终导致重大影响接口性能。

默认的 HttpMessageConverter 汇合:

局部要害代码如下。

org/springframework/boot/autoconfigure/http/HttpMessageConverters.<init>:

org/springframework/http/converter/json/Jackson2ObjectMapperBuilder.registerWellKnownModulesIfAvailable:

org/springframework/util.ClassUtils.forName:

org/springframework/http/converter/xml/SourceHttpMessageConverter:

javax/xml/transform/FactoryFinder.find:

文章中对于这个问题还提供了两种解决办法:

第一种办法,就是我最后倡议的引入 jackson-datatype-joda 依赖,防止每次初始化默认的 MappingJackson2HttpMessageConverter 时 ClassLoader 重复加载不在 classpath 中的 com.fasterxml.jackson.datatype.joda.JodaModule 和 com.fasterxml.jackson.datatype.joda$JodaModule。

第二种办法,不初始化默认的 HttpMessageConverter。因为咱们此处只须要应用自定义的 FastJsonHttpMessageConverter 来执行编解码,齐全能够防止执行 getDefaultConverters 办法,反复初始化许多用不到的默认的 HttpMessageConverter。因而在 new HttpMessageConverters 对象时,能够将 addDefaultConverters 参数设置为 false。

ObjectFactory<HttpMessageConverters> objectFactory = () -> new HttpMessageConverters(false, new HttpMessageConverter[] {(HttpMessageConverter)fastJsonHttpMessageConverter });

实际上,咱们还能够批改 DefaultFeignConfig 中 ObjectFactory<HttpMessageConverters> 的实现,防止每次都 new 一个新的 HttpMessageConverters 对象(反复初始化 HttpMessageConverters),实现进一步优化。
故倡议相干业务开发,将 DefaultFeignConfig 批改成如下代码:

在相干业务开发将新旧版本代码中的 DefaultFeignConfig 都进行改良并部署到 FAT(测试)环境当前,我在本人本机用 JMeter 对 FAT 环境进行了模仿压测。

旧版改良后压测后果:

新版改良后压测后果:

发现此时,两个版本的接口性能曾经基本相同。

最终测试人员在 UAT 环境,对降级框架并改良 DefaultFeignConfig 后的代码再次进行压测,压测后果如下:

吞吐量从最后不达标的 6.4/s,晋升到了 160.4/s。

那为什么 war to jar 部署的调整,会导致类加载器在频繁查找和加载资源时性能有所降落呢?

在对 SpringBoot 可执行 jar 的原理做了一番理解当前。狐疑和 Spring Boot 为了做到可能以一个 fat jar 来启动,从而扩大了 JDK 的 JarFile URL 协定,并定制了本人的 ClassLoader 和 jar 文件协定的 Hander,实现了 jar in jar、jar in directory 的加载形式无关。

对 SpringBoot 可执行 jar 原理感兴趣的敌人能够参考:《可执行 jar 包》。

War2Jar 类加载器性能降落根因探索

为了验证本人的猜想,我在本人本机搭建了一个简略的 Demo。

Demo 中有两个服务,A 和 B。将 A 和 B 都注册到 Eureka 注册核心,并且 A 通过 Feign 调用 B。

接下来应用 Jmeter 在雷同的配置下对各种场景进行压测,并在压测过程中应用 Arthas 的 profiler 命令生成各种场景下的火焰图。

压测后果如下(-Xms512m -Xmx512m):

通过比照表格三和表格四能够得悉,代码优化后,是否引入依赖,对吞吐量简直没有影响。

通过表格三和表格四能够得悉,代码优化后,在不会频繁查找和加载不存在的资源时,三种部署形式的吞吐量基本一致。

通过表格二能够得悉,在频繁应用 SPI 获取 classpath 下查找不到的实现时,Tomcat war 部署性能更好。

通过表格一能够得悉,在频繁加载不存在的类时,将 jar 包解压后通过 JarLauncher 启动性能更好。

比照表格一中 ③ 和 ② 类似栈的火焰图:

能够发现两者在 org/springframework/boot/loader/LaunchedURLClassLoader.loadClass 加载类时,存在差别。

② 不仅会执行 java/lang/ClassLoader.loadClass,还会执行 org/springframework/boot/loader/LaunchedURLClassLoader.definePackageIfNecessary。

查看 org/springframework/boot/loader/LaunchedURLClassLoader.loadClass 的源码:

发现存在一个条件分支。

查看 org/springframework/boot/loader/Launcher.createArchive 的源码:

发现这个条件的值与利用是 可执行 jar 文件 还是 文件目录 无关。

对 ② 再次进行压测,并 trace org/springframework/boot/loader/LaunchedURLClassLoader.definePackageIfNecessary:

`---[165.770773ms] org.springframework.boot.loader.LaunchedURLClassLoader:definePackageIfNecessary()
    +---[0.00347ms] org.springframework.boot.loader.LaunchedURLClassLoader:getPackage() #197
    `---[165.761244ms] org.springframework.boot.loader.LaunchedURLClassLoader:definePackage() #199

发现这个中央的确存在比拟耗时的状况。

浏览该局部源码,从正文中即可得悉,definePackageIfNecessary 次要是为了在调用 findClass 之前尝试依据类名去定义类所在的 package,确保 jar 文件嵌套 jar 包里的 manifest 可能和 package 关联起来。

Debug definePackageIfNecessary 这部分代码,发现在 definePackage 时,会遍历 BOOT-INF/lib/ 下所有的 jar 包 以及 BOOT-INF/classes/。如果发现这些资源中存在指定的类,就持续调用 definePackage 办法,否则遍历完间接返回 null。

后面说过,每一次 Feign 调用都会加载 4 次不在 classpath 中的 com.fasterxml.jackson.datatype.joda.JodaModule 和 com.fasterxml.jackson.datatype.joda$JodaModule(共 8 次)。而我这个简略的 Demo 利用依赖的 jar 有 117 个(理论企业级我的项目将会更多)。那么每一次 Feign 调用,就会执行 8 * (117 + 1),总计 944 次循环里的逻辑。而逻辑中的 org.springframework.boot.loader.jar.Handler.openConnection 办法在执行过程中又会波及到比拟耗时的 IO 操作,最终导致重大影响接口性能。从生成的火焰图中,也能够看到这部分解决逻辑。

至此,曾经能够确认 war to jar 部署的调整,导致类加载器在频繁查找和加载资源时性能有所降落的根因就是:Spring Boot 为了做到可能以一个 fat jar 来启动,减少了一些定制的解决逻辑,而这部分定制的解决逻辑在频繁执行时,会对程序性能产生较大影响。

至于 [为什么在频繁加载不存在的类时,将 jar 包解压后通过 JarLauncher 启动比 Tomcat war 部署性能更好?]、[在频繁应用 SPI 获取 classpath 下查找不到的实现时,Tomcat war 部署又比将 jar 包解压后通过 JarLauncher 启动性能更好?],受限于篇幅,就不在本文中持续开展了。感兴趣的敌人能够依照本文中介绍的办法,再联合相干源码进行进一步探索。

总结

大家在自定义 Feign 的编解码器时,如果用到了 SpringEncoder / SpringDecoder,应防止 HttpMessageConverters 的反复初始化。如果不须要应用那些默认的 HttpMessageConverter,能够在初始化 HttpMessageConverters 时将第一个入参设置为 false,从而不初始化那些默认的 HttpMessageConverter。

另外,应该理解不同的部署形式在类加载器频繁查找和加载资源时是存在性能差别的。

咱们在写代码时,也应该要防止反复初始化,以及重复查找和加载不存在的资源。

最初,善用 SkyWalking 和 Arthas 能够帮忙咱们更加高效地排查程序谬误和性能瓶颈。

彩蛋

如果利用应用了 SkyWalking Agent,再应用 Arthas,可能会遇到 Arthas 局部命令(trace、watch 等会对类进行加强的命令)不能失常工作的问题。

解决方案:https://github.com/apache/skywalking/blob/master/docs/en/FAQ/Compatible-with-other-javaagent-bytecode-processing.md

而当 Arthas 能够失常工作当前,咱们对于 SkyWalking Agent 曾经加强过的类的办法执行 trace 等命令时,最好在办法名前面加上一个 * 符号进行含糊匹配。Arthas 最终会将所有匹配办法的 trace 追踪后果进行汇总展现。

办法名不加 * 进行 trace:

办法名加上 * 进行 trace:

能够看到办法名加上 * 当前,trace 失去的后果才是咱们现实的后果。

这是因为 SkyWalking Agent 应用了 ByteBuddy 做字节码加强。而 ByteBuddy 每加强一个办法,都会为该办法生成一个辅助外部类(HelloController$auxiliary$jiu2bTqU),并且会对以后类(HelloController)中的原办法(test1)进行重命名(test1$original$lyu0XDob),并生成一个与原办法同名的办法(test1)和一个不同名但仅供辅助外部类调用的办法(test1$original$lyu0XDob$accessor$8F82ImAF)。

应用共事开发的 Java 反编译工具能够直观地看到相干代码:

另外,在应用 Arthas 的时候,倡议抉择最新的版本。比方,3.4.2 以前的版本 trace 追踪大办法时就可能会导致 JVM Metaspace OOM。详情见:《记一次由 Arthas 引起的 Metaspace OOM 问题》。

如果你想要基于 Arthas 打造企业级在线诊断平台,能够参考《工商银行打造在线诊断平台的摸索与实际》。

作者简介

王瑞显,开源爱好者,现任掌门教育基础架构部研发工程师,次要负责公司全链路监控零碎和利用诊断平台的研发。

欢送登陆 start.aliyun.com 知口头手实验室体验 Arthas 57 个入手试验:https://start.aliyun.com/handson-lab/#!category=arthas

Arthas 试验预览

为了让更多开发者开始用上 Arthas 这个 Java 诊断神器,Arthas 社区联结 JetBrains 推出 Arthas 有奖征文活动:聊聊这些年你和 Arthas 之间的那些事儿。流动仍在炽热进行中,点击即可参加,欢送大家踊跃投稿,参加即有可能获奖!

正文完
 0