我找到了一個快速定位SpringBoot介面超時問題的神器!

語言: CN / TW / HK

文章來源: https://juejin.cn/post/7140462361759973384

背景

公司有個渠道系統,專門對接三方渠道使用,沒有什麼業務邏輯,主要是轉換報文和引數校驗之類的工作,起著一個承上啟下的作用。

最近在優化介面的響應時間,優化了程式碼之後,但是時間還是達不到要求;有一個詭異的100ms左右的耗時問題,在介面中列印了請求處理時間後,和呼叫方的響應時間還有差了100ms左右。比如程式裡記錄150ms,但是呼叫方等待時間卻為250ms左右。

下面記錄下當時詳細的定位&解決流程(其實解決很簡單,關鍵在於怎麼定位並找到解決問題的方法)

一、定位過程

分析程式碼

渠道系統是一個常見的spring-boot web工程,使用了整合的tomcat。 分析了程式碼之後,發現並沒有特殊的地方,沒有特殊的過濾器或者攔截器,所以初步排除是業務程式碼問題

分析呼叫流程

出現這個問題之後,首先確認了下介面的呼叫流程。由於是內部測試,所以呼叫流程較少。

Nginx -反向代理-> 渠道系統

公司是雲伺服器,網路走的也是雲的內網。由於不明確問題的原因,所以用排除法,首先確認伺服器網路是否有問題。

先確認傳送端到Nginx Host是否有問題:

[jboss@VM_0_139_centos ~]$ ping 10.0.0.139
PING 10.0.0.139 (10.0.0.139) 56(84) bytes of data.
64 bytes from 10.0.0.139: icmp_seq=1 ttl=64 time=0.029 ms
64 bytes from 10.0.0.139: icmp_seq=2 ttl=64 time=0.041 ms
64 bytes from 10.0.0.139: icmp_seq=3 ttl=64 time=0.040 ms
64 bytes from 10.0.0.139: icmp_seq=4 ttl=64 time=0.040 ms

從ping結果上看,傳送端到Nginx主機的延遲是無問題的,接下來檢視Nginx到渠道系統的網路。

# 由於日誌是沒問題的,這裡直接複製上面日誌了
[jboss@VM_0_139_centos ~]$ ping 10.0.0.139
PING 10.0.0.139 (10.0.0.139) 56(84) bytes of data.
64 bytes from 10.0.0.139: icmp_seq=1 ttl=64 time=0.029 ms
64 bytes from 10.0.0.139: icmp_seq=2 ttl=64 time=0.041 ms
64 bytes from 10.0.0.139: icmp_seq=3 ttl=64 time=0.040 ms
64 bytes from 10.0.0.139: icmp_seq=4 ttl=64 time=0.040 ms

從ping結果上看,Nginx到渠道系統伺服器網路延遲也是沒問題的

既然網路看似沒問題,那麼可以繼續排除法,砍掉Nginx,客戶端直接再渠道系統的伺服器上,通過迴環地址(localhost)直連,避免經過網絡卡/dns,縮小問題範圍看看能否復現(這個應用和地址是我後期模擬的,測試的是一個空介面):

[jboss@VM_10_91_centos tmp]$ curl -w "@curl-time.txt" http://127.0.0.1:7744/send
success
http: 200
dns: 0.001s
redirect: 0.000s
time_connect: 0.001s
time_appconnect: 0.000s
time_pretransfer: 0.001s
time_starttransfer: 0.073s
size_download: 7bytes
speed_download: 95.000B/s
----------
time_total: 0.073s 請求總耗時

從curl日誌上看,通過迴環地址呼叫一個空介面耗時也有73ms。這就奇怪了,跳過了中間所有呼叫節點(包括過濾器&攔截器之類),直接請求應用一個空介面,都有73ms的耗時,再請求一次看看:

[jboss@VM_10_91_centos tmp]$ curl -w "@curl-time.txt" http://127.0.0.1:7744/send
success
http: 200
dns: 0.001s
redirect: 0.000s
time_connect: 0.001s
time_appconnect: 0.000s
time_pretransfer: 0.001s
time_starttransfer: 0.003s
size_download: 7bytes
speed_download: 2611.000B/s
----------
time_total: 0.003s

更奇怪的是,第二次請求耗時就正常了,變成了3ms。經查閱資料,linux curl是預設開啟http keep-alive的。就算不開啟keep-alive,每次重新handshake,也不至於需要70ms。

經過不斷分析測試發現,連續請求的話時間就會很短,每次請求只需要幾毫秒,但是如果隔一段時間再請求,就會花費70ms以上。

從這個現象猜想,可能是某些快取機制導致的,連續請求因為有快取,所以速度快,時間長快取失效後導致時間長。

那麼這個問題點到底在哪一層呢?tomcat層還是spring-webmvc呢?

光猜想定位不了問題,還是得實際測試一下,把渠道系統的程式碼放到本地ide裡啟動測試能否復現

但是匯入本地Ide後,在Ide中啟動後並不能復現問題,並沒有70+ms的延遲問題。這下頭疼了,本地無法復現,不能Debug,由於問題點不在業務程式碼,也不能通過加日誌的方式來Debug

這時候可以祭出神器Arthas了

二、Arthas分析問題

Arthas 是Alibaba開源的Java診斷工具,深受開發者喜愛。 當你遇到以下類似問題而束手無策時, Arthas可以幫助你解決:

1、這個類從哪個 jar 包載入的?為什麼會報各種類相關的 Exception?

2、我改的程式碼為什麼沒有執行到?難道是我沒 commit?分支搞錯了?

3、遇到問題無法在線上 debug,難道只能通過加日誌再重新發布嗎?

4、線上遇到某個使用者的資料處理有問題,但線上同樣無法 debug,線下無法重現!

5、是否有一個全域性視角來檢視系統的執行狀況?

6、有什麼辦法可以監控到JVM的實時執行狀態?

上面是Arthas的官方簡介,這次我只需要用他的一個 小功能  trace  。 動態計算方法呼叫路徑和時間,這樣我就可以定位時間在哪個地方被消耗了。

1、trace 方法內部呼叫路徑,並輸出方法路徑上的每個節點上耗時

2、trace 命令能主動搜尋 class-pattern/method-pattern

3、對應的方法呼叫路徑,渲染和統計整個呼叫鏈路上的所有效能開銷和追蹤呼叫鏈路。

有了神器,那麼該追蹤什麼方法呢? 由於我對Tomcat原始碼不是很熟,所以只能從spring mvc下手,先來trace一下spring mvc的入口:

[jboss@VM_10_91_centos tmp]$ curl -w "@curl-time.txt" http://127.0.0.1:7744/send
success
http: 200
dns: 0.001s
redirect: 0.000s
time_connect: 0.001s
time_appconnect: 0.000s
time_pretransfer: 0.001s
time_starttransfer: 0.115s
size_download: 7bytes
speed_download: 60.000B/s
----------
time_total: 0.115s

本次呼叫,呼叫端時間花費115ms,但是從arthas trace上看,spring mvc只消耗了18ms,那麼剩下的97ms去哪了呢?

本地測試後已經可以排除spring mvc的問題了,最後也是唯一可能出問題的點就是tomcat

可是本人並不熟悉tomcat中的原始碼,就連請求入口都不清楚,tomcat裡需要trace的類都不好找。。。

不過沒關係,有神器Arthas,可以通過stack命令來反向查詢呼叫路徑,以   org.springframework.web.servlet.DispatcherServlet 作為引數:

stack 輸出當前方法被呼叫的呼叫路徑

很多時候我們都知道一個方法被執行,但這個方法被執行的路徑非常多,或者你根本就不知道這個方法是從那裡被執行了,此時你需要的是 stack 命令。

從stack日誌上可以很直觀的看出DispatchServlet的呼叫棧,那麼這麼長的路徑,該trace哪個類呢(這裡跳過spring mvc中的過濾器的trace過程,實際排查的時候也trace了一遍,但這詭異的時間消耗不是由這裡過濾器產生的)?

有一定經驗的老司機從名字上大概也能猜出來從哪裡下手比較好,那就是  org.apache.coyote.http11.Http11Processor.service  ,從名字上看,http1.1處理器,這可能是一個比較好的切入點。下面來trace一下:

日誌裡有一個129ms的耗時點(時間比沒開arthas的時候更長是因為arthas本身帶來的效能消耗,所以生產環境小心使用),這個就是要找的問題點。

打問題點找到了,那怎麼定位是什麼導致的問題呢,又如何解決呢?

繼續trace吧,細化到具體的程式碼塊或者內容。trace由於效能考慮,不會展示所有的呼叫路徑,如果呼叫路徑過深,只有手動深入trace,原則就是trace耗時長的那個方法:

一段無聊的手動深入trace之後………………

發現了一個值得暫停思考的點:

+---[min=0.004452ms,max=34.479307ms,total=74.206249ms,count=31] org.apache.catalina.webresources.TomcatJarInputStream:getNextJarEntry() #117

這行程式碼載入了31次,一共耗時74ms;從名字上看,應該是tomcat載入jar包時的耗時,那麼是載入了31個jar包的耗時,還是載入了jar包內的某些資源31次耗時呢?

TomcatJarInputStream這個類原始碼的註釋寫到:

The purpose of this sub-class is to obtain references to the JarEntry objects for META-INF/ and META-INF/MANIFEST.MF that are otherwise swallowed by the JarInputStream implementation.

大概意思也就是,獲取jar包內META-INF/,META-INF/MANIFEST的資源,這是一個子類,更多的功能在父類JarInputStream裡。

其實看到這裡大概也能猜到問題了,tomcat載入jar包內META-INF/,META-INF/MANIFEST的資源導致的耗時,至於為什麼連續請求不會耗時,應該是tomcat的快取機制(下面介紹原始碼分析)

不著急定位問題,試著通過Arthas最終定位問題細節,繼續手動深入trace

[arthas@24851]$ trace org.apache.catalina.webresources.TomcatJarInputStream *
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:4) cost in 44 ms.
`---ts=2019-09-14 21:37:47;thread_name=http-nio-7744-exec-5;id=14;is_daemon=true;priority=5;TCCL=org.springframework.boot.loader.LaunchedURLClassLoader@20ad9418
`
---[0.234952ms] org.apache.catalina.webresources.TomcatJarInputStream:createZipEntry()
+---[0.039455ms] java.util.jar.JarInputStream:createZipEntry() #43
`---[0.007827ms] java.lang.String:equals() #44

`
---ts=2019-09-14 21:37:47;thread_name=http-nio-7744-exec-5;id=14;is_daemon=true;priority=5;TCCL=org.springframework.boot.loader.LaunchedURLClassLoader@20ad9418
`---[0.050222ms] org.apache.catalina.webresources.TomcatJarInputStream:createZipEntry()
+---[0.001889ms] java.util.jar.JarInputStream:createZipEntry() #43
`
---[0.001643ms] java.lang.String:equals() #46
#這裡一共31個trace日誌,刪減了剩下的

從方法名上看,還是載入資源之類的意思。都已經到jdk原始碼了,這時候來看一下  TomcatJarInputStream  這個類的原始碼:

/**
* Creates a new <code>JarEntry</code> (<code>ZipEntry</code>) for the
* specified JAR file entry name. The manifest attributes of
* the specified JAR file entry name will be copied to the new
* <CODE>JarEntry</CODE>.
*
* @param name the name of the JAR/ZIP file entry
* @return the <code>JarEntry</code> object just created
*/

protected ZipEntry createZipEntry(String name) {
JarEntry e = new JarEntry(name);
if (man != null) {
e.attr = man.getAttributes(name);
}
return e;
}

這個   createZipEntry   有個name引數,從註釋上看,是jar/zip檔名,如果能得到檔名這種關鍵資訊,就可以直接定位問題了;還是通過Arthas,使用watch命令,動態監測方法呼叫資料

watch方法執行資料觀測

讓你能方便的觀察到指定方法的呼叫情況。能觀察到的範圍為:返回值、丟擲異常、入參,通過編寫 OGNL 表示式進行對應變數的檢視。

watch 該方法的入參

這下直接看到了具體載入的資源名,這麼熟悉的名字:swagger-ui,一個國外的rest介面文件工具,又有國內開發者基於swagger-ui做了一套spring mvc的整合工具,通過註解就可以自動生成swagger-ui需要的介面定義json檔案,用起來還比較方便,就是侵入性較強。

刪除swagger的jar包後問題,詭異的70+ms就消失了

<!--pom 裡刪除這兩個引用,這兩個包時國內開發者封裝的,swagger-ui並沒有提供java spring-mvc的支援包,swagger只是一個瀏覽器端的ui+editor -->
<dependency>
<groupId>io.springfox</groupId>
<artifactId>springfox-swagger2</artifactId>
<version>2.9.2</version>
</dependency>
<dependency>
<groupId>io.springfox</groupId>
<artifactId>springfox-swagger-ui</artifactId>
<version>2.9.2</version>
</dependency>

那麼為什麼swagger會導致請求耗時呢,為什麼每次請求偶讀會載入swagger內部的靜態資源呢?

其實這是tomcat-embed的一個bug吧,下面詳細介紹一下該Bug

三、Tomcat embed Bug分析&解決

原始碼分析過程實在太漫長,而且也不是本文的重點,所以就不介紹了, 下面直接介紹下分析結果

順便貼一張tomcat處理請求的核心類圖

1、為什麼每次請求會載入Jar包內的靜態資源

關鍵在於  org.apache.catalina.mapper.Mapper#internalMapWrapper   這個方法,該版本下處理請求的方式有問題,導致每次都校驗靜態資源。

2、為什麼連續請求不會出現問題

因為Tomcat對於這種靜態資源的解析是有快取的,優先從快取查詢,快取過期後再重新解析。具體參考 org.apache.catalina.webresources.Cache  ,預設過期時間ttl是5000ms。

3、為什麼本地不會復現

其實確切的說,是通過spring-boot打包外掛後 不能復現。 由於啟動方式的不同,tomcat使用了不同的類去處理靜態資源,所以沒問題

4、如何解決

升級tomcat-embed版本即可

當前出現Bug的版本為:

spring-boot:2.0.2.RELEASE,內建的tomcat embed版本為8.5.31

升級tomcat embed版本至8.5.40+即可解決此問題,新版本已經修復了

通過替換springboot pom properties方式

如果專案是maven是繼承的springboot,即parent配置為springboot的,或者dependencyManagement中import spring boot包的

<parent>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-parent</artifactId>
<version>2.0.2.RELEASE</version>
<relativePath/> <!-- lookup parent from repository -->
</parent>

pom中直接覆蓋properties即可:

<properties>
<tomcat.version>8.5.40</tomcat.version>
</properties>

5、升級spring boot版本

springboot 2.1.0.RELEASE中的tomcat embed版本已經大於8.5.31了,所以直接將springboot升級至該版本及以上版本就可以解決此問題!

歡迎掃碼加入儒猿技術交流群,每天晚上20:00都有Java面試、Redis、MySQL、RocketMQ、SpringCloudAlibaba、Java架構等技術答疑分享,更能跟小夥伴們一起交流技術

另外推薦儒猿課堂的1元系列課程給您,歡迎加入一起學習~

網際網路Java工程師面試突擊課

(1元專享)

SpringCloudAlibaba零基礎入門到專案實戰

(1元專享)

億級流量下的電商詳情頁系統實戰專案

(1元專享)

Kafka訊息中介軟體核心原始碼精講

(1元專享)

12個實戰案例帶你玩轉Java併發程式設計

(1元專享)

Elasticsearch零基礎入門到精通

(1元專享)

基於Java手寫分散式中介軟體系統實戰

(1元專享)

基於ShardingSphere的分庫分表實戰課

(1元專享)