本文已整理致我的 github地址，歡迎大家 star 支援一下

大家好，我是坤哥

今天給大家分享一個這兩天排查成功的案例，相信對大家會有些幫助。

大多數人應該聽過一道經典的面試題：請詳細地說出從瀏覽器位址列輸入 url 到最終呈現出結果的過程，越詳細越好，為什麼面試官這麼喜歡問這道題呢，因為這個題涉及的面非常廣，知識點非常多，如果你能完全吃透，非常有助於排查一些疑難雜症，今天我要分享的這個 case 就是個典型，廢話不多說，進入正題。

問題描述

前端同學發現新開發的專案介面有 1/3 概率出現 RTT（請求往返時間）大於 3 s 的情況，以登入介面為例，Chrome 請求所花時間如下

正常的 RTT 在幾十 ms 左右（登入介面在 100 ms 左右），所以 3s 這個時延肯定不正常，於是著手排查，由於每個介面都可能超過 3s，所以下文皆以登入介面分析為例，因為登入介面邏輯相對比較簡單。

排查思路

1. 排除瀏覽器本身的問題

估計大家看到這種問題馬上就斷定是 server 的問題，立馬開始著手排查 server 的問題，不急，我們要先把瀏覽器本身可能導致請求緩慢的問題給排除了，瀏覽器本身可能因為「請求最大併發數量限制」，「更高優先順序的請求插隊，低優先順序的任務被延後」等原因導致請求緩慢

所以為了排除瀏覽器本身造成的網路請求過慢，我們最好找一個其它的瀏覽器比如 Safari 或者終端 curl 請求來再重試下這個請求，看下請求是否依然緩慢，這裡我兩個方法都試了，用 Safari 也重現了 RTT 大於 3s 的情況，並且我用 curl 在終端請求也發現了 RTT 大於 3s 的情況，如何使用 curl 請求呢，這裡提醒一下，大家千萬不要傻傻地去構建一個 curl 請求，瀏覽器的網路請求本身可以匯出成 curl 的形式的，在「network」中點選網路請求，選中「Copy as cURL」，就可獲取此請求的 curl 表示方式

獲得 curl 請求後，對此請求稍加改造，加上如下 -o,-s, -w 選項

curl-o/dev/null-s-w"time_connect:%{time_connect}\ntime_starttransfer:
%{time_starttransfer}\ntime_nslookup:%{time_namelookup}\ntime_total:%{time_total}\n"
瀏覽器copy而來的請求

畫外音：這裡對幾個引數簡要作下說明: -o /dev/null 遮蔽原有輸出資訊，-s 靜默模式，不輸出任何東西，-w %{http_code} 控制額外輸出

請求後會出現類似以下的結果

time_connect:0.045897
time_starttransfer:3.064762
time_nslookup:0.004328
time_total:3.064777
 

前面幾個引數就不多做說明了，一般我們只要關心最後一個 time_total 引數即可，表示請求花費的全部時間。

綜上，經過 safari 與 終端測試發現登入介面都有超過 3s 的現象出現，就此可以排除客戶端的問題，接下來就是我們的重頭戲：服務端排查！

2. 服務端排查

我們的 server 端是一個 Spring MVC 服務，對於登入介面來說，它的邏輯如下

@RestController
@RequestMapping(path="/api/auth",method=RequestMethod.POST)
@Slf4j
publicclassAuthController{
@RequestMapping(params="member.login")
publicResultTO<TokenDTO>login(@RequestBodyUserLoginDTOuserLogin){
/**這裡寫登入邏輯*/
returnResultTO.responseSuccess(tokenDTO);
}
}

裡面的邏輯其實非常簡單，就是根據使用者名稱輸入的賬號密碼去 db 請求一下校驗使用者資訊是否正確，正確則生成 jwt token 返回給前端，看起來沒啥問題，當然為了確保這段邏輯確實沒問題，我們可以用一些工具來幫助我們實時驗證一下，這裡推薦一款阿里開源的 Java 診斷工具：Arthas，採用命令列互動模式，提供了豐富的功能，是排查 jvm 相關問題的利器，簡單列舉一下它的功能：

• 提供效能看板，包括執行緒、cpu、記憶體等資訊，並且會定時的重新整理。
• 根據各種條件檢視執行緒快照。比如找出cpu佔用率最高的 n 個執行緒等
• 輸出jvm的各種資訊，如 gc 演算法、jdk 版本、ClassPath 等
• 檢視/設定sysprop和sysenv
• 檢視某個類的靜態屬性，也可以通過 ognl 語法執行一些語句
• 檢視已載入的類的詳細資訊，比如這個類從哪個 jar 包載入的。也可以檢視類的方法的資訊
• dump 某個類的位元組碼到指定目錄
• 直接反編譯指定的類
• 檢視類載入器的一些資訊
• 可以讓jvm重新載入某個類
• 監控方法的執行，同時可以獲取到執行的入參、出參以及丟擲的異常
• 追蹤方法執行的呼叫棧，以及各個方法的呼叫時間

這裡我們要用到它的最後一項功能，實時檢視各個方法的呼叫時間，整個使用 arthas 的步驟如下

1、 首先我們要先下載一下 arthas，如下

curl-Ohttps://arthas.aliyun.com/arthas-boot.jar

2、 啟動 arthas，啟動後會展示一個 java 程序列表，我們選中 Arthas 將要除錯的 Spring MVC 程序，以下選中 2，然後即可進入 arthas 的互動式介面（以下 arthas 展示的其實不只這麼多資訊，過濾了不少描述性的資訊，只保留對大家有用的核心資訊）

[root@d-sts-sh-1-spring-mvc-service-0buser]#/opt/java8/bin/java-jararthas-boot.jar
[INFO]arthas-bootversion:3.5.1
[INFO]Foundexistingjavaprocess,pleasechooseoneandinputtheserialnumberoftheprocess,eg:1.ThenhitENTER.
*[1]:99org.apache.flume.node.Application
[2]:2698/opt/apps/business/spring-mvc-service.jar
2
[arthas@2698]$

然後我們就可以用 arthas 的 trace 命令來追蹤方法呼叫,什麼是 trace 命令，官方對其功能的介紹如下：

追蹤方法內部呼叫路徑，並輸出方法路徑上的每個節點上耗時，trace 命令能主動搜尋 class-pattern／method-pattern 對應的方法呼叫路徑，渲染和統計整個呼叫鏈路上的所有效能開銷和追蹤呼叫鏈路。

現在我們要跟蹤 login 的實時耗時，那就可以指定「trace + 此方法所在類的全限定名（包名+類名）+方法名」來跟蹤了，如下

[arthas@2698]$tracecom.xxx.AuthControllerlogin

然後在瀏覽器執行登入操作，當瀏覽器登入時間為 3s+ 時， trace 對應的追蹤結果如下

可以看到登入只花費了 76 ms，遠達不到 3 s，那是否可以就此斷定此臺機器服務沒問題呢？
PS：我們線上的 SpringMVC 服務部署了兩臺機器，另一臺機器也打開了 arthas 除錯，也是 76 ms 左右

答案是不行，我們先來看一下 Spring MVC 的請求流轉圖

上圖黃色部分的處理器即處理業務邏輯的 Controller，可以看到從請求到 Controller 還要經過 filter chain，DispatcherService 等類，在最開始的 filter chain 中，紫色的 JwtAuthorizationFilter 是我們自定義的 filter，是否有可能是這個 filter 處理過慢導致的呢，所以我們最好在請求的起始點 OncePerRequestFilter 的 doFilter 方法（實際上在此 filter 之前還要經過不少流轉，不過在此之前都是框架的正常處理流程，可忽略） 來執行 arthas 的 trace。

當瀏覽器的登入請求為 3s+ 時，再次觀察此次的 trace 結果：

也不過區區 81 ms! 在生產的兩臺機器上都試了多次，結論為當前端請求為 3s 時，兩臺機器的執行時間都為 81 ms 左右！至此可以斷定線上的兩臺機器 SpringMVC 服務是沒有問題的！既然線上機器服務沒有問題，那隻能從流量的流轉路徑著手了，客戶端發出請求要經過哪些流程才能到達 SpringMVC 服務？

可以看到請求需要經過反向代理層，接入層後才能到達我們的站點層（即我們的 Spring MVC 服務），也就是說從「反向代理層到接入層」及「接入層到站點層」都可能導致請求緩慢，於是我把我用 arthas trace 執行的結果（MVC 服務執行時間 80ms 左右）與前端請求有 1/3 的概率超過 3s 的結論告訴了運維，讓他們排查一下從反向代理層到站點層這中間是否有啥問題，不一會兒果然查出了問題。

結論是這樣的：本來 MVC 服務的機器有三臺，後來縮容了一臺，變成了兩臺，但接入層 kongfu 依然持有這臺被縮容的機器 ip，沒有將其踢掉，所以前端流量打進來後，由於接入層的負載均衡策略，請求是有 1/3 的概率打到這臺下線機器的 ip 上的，由於這個 ip 對應的機器無法響應這個請求，等到超時後，kongfu 會重試把這個請求打到另外正常的兩臺機器中的任意一臺，也就是說請求 3s 中的大部分時間花在了等待那臺不正常的 ip 機器響應上了。

有人可能會問，機器被踢掉了，接入層 kongfu 應該是能檢測其下線的吧，怎麼還會給這臺下線的機器發請求呢？

是的，kongfu 會通過埠檢測來檢測機器是否存活的，但問題是，這臺被縮容的機器雖然被回收了，但它的 ip 也是可以重新被分配給其他機器的，這種情況下 kongfu 通過埠檢測就會認為它持有的 ip 對應的機器是存活的，而這臺被分配此 ip 的機器又剛好不是 Spring MVC 服務，那正常 MVC 請求打給它的話，它就無法處理了，只能等到請求超時再由 kongfu 重試轉發給正常的機器。

有人可能會好奇，運維是怎麼查出來的呢，通過 「curl -I www.example」的形式可以輸出開頭資訊,然後加上 -b 選項可以帶上 cookie，我們的接入層如果發現請求裡帶有某些特殊的 cookie 會返回一個名為「X-KF-Via」的頭欄位，如下

X-KF-Via:agw(bip=10.65.x.1:8001,10.65.x.2:8001;b=mvc_service)

這個頭欄位表示，請求 mvc_service 服務總共請求了兩臺機器，第一臺 10.65.x.1 未成功後，再接著重試 10.65.x.2:8001，所以由此可以排查出 10.65.x.1 這臺機器有問題，所以你看熟悉系統架構有多重要，如果我早知道有這麼一個選項，就可以一步到位排查出此問題了

知道了問題所在，處理方案就很簡單了，直接把這臺有問題的機器從 kongfu 摘掉就行了

總結

排查的思路其實相對比較清晰，但一定要對請求的整個流轉流程有一個比較清醒的認識，這樣才能快速判斷出問題所在，現在再回頭看下開頭的那道經典面試題「請詳細地說出從瀏覽器位址列輸入 url 到最終呈現出結果的過程，越詳細越好」，相信你會頗有感觸，這道面試題如果你對請求流轉的每個點都吃透得話，將極大地提升你排查解決問題的能力，舉個例子，之前就有人反饋這樣的一個問題：

在做 Server 壓力測試時發現，客戶端給伺服器不斷髮請求，並接受伺服器端的響應。發現接收伺服器響應的過程中，會出現 recv 伺服器端響應，阻塞 40ms 的情況，但是檢視 server 端日誌，Server 都在 2ms 內將請求處理完成，並給客戶端響應

如果你瞭解 TCP，就知道它是由於 TCP 的延遲確認機制和 Nagle 演算法及擁塞控制導致的，自然而然就會朝著這個方向 去解決了，比如開啟 TCP_NODELAY 選項等。