作者 | 王瑞顯? 掌門教育基礎架構部研發工程師
來源|阿里巴巴云原生公眾號

背景

接收到公司業務部門的開發反饋，應用在升級公司內部框架后，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:() 比較耗時，并繼續一層層 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.getObject()).getConverters() 獲取 HttpMessageConverters。而我們自定義的 DefaultFeignConfig 中配置的ObjectFactory 的實現是每次都 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.：

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 的實現，避免每次都 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 之間的那些事兒。**活動仍在火熱進行中，點擊即可參與，歡迎大家踴躍投稿，參與即有可能獲獎！

總結

以上是生活随笔為你收集整理的Spring Boot 微服务性能下降九成！使用 Arthas 定位根因的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。