為了解決這個 RTT 過長的問題，我祭出了大招！

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

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

問題描述

前端同學(xué)發(fā)現(xiàn)新開發(fā)的項目接口有 1/3 概率出現(xiàn) RTT（請求往返時間）大于 3 s 的情況，以登錄接口為例，Chrome 請求所花時間如下

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

排查思路

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

估計大家看到這種問題馬上就斷定是 server 的問題，立馬開始著手排查 server 的問題，不急，我們要先把瀏覽器本身可能導(dǎo)致請求緩慢的問題給排除了，瀏覽器本身可能因為「請求最大并發(fā)數(shù)量限制」，「更高優(yōu)先級的請求插隊，低優(yōu)先級的任務(wù)被延后」等原因?qū)е抡埱缶徛?/p>

所以為了排除瀏覽器本身造成的網(wǎng)絡(luò)請求過慢，我們最好找一個其它的瀏覽器比如 Safari 或者終端 curl 請求來再重試下這個請求，看下請求是否依然緩慢，這里我兩個方法都試了，用 Safari 也重現(xiàn)了 RTT 大于 3s 的情況，并且我用 curl 在終端請求也發(fā)現(xiàn)了 RTT 大于 3s 的情況，如何使用 curl 請求呢，這里提醒一下，大家千萬不要傻傻地去構(gòu)建一個 curl 請求，瀏覽器的網(wǎng)絡(luò)請求本身可以導(dǎo)出成 curl 的形式的，在「network」中點擊網(wǎng)絡(luò)請求，選中「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而來的請求

畫外音：這里對幾個參數(shù)簡要作下說明: -o /dev/null 屏蔽原有輸出信息，-s  靜默模式，不輸出任何東西，-w %{http_code} 控制額外輸出

請求后會出現(xiàn)類似以下的結(jié)果

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

前面幾個參數(shù)就不多做說明了，一般我們只要關(guān)心最后一個 time_total 參數(shù)即可，表示請求花費的全部時間。

綜上，經(jīng)過 safari 與 終端測試發(fā)現(xiàn)登錄接口都有超過 3s 的現(xiàn)象出現(xiàn)，就此可以排除客戶端的問題，接下來就是我們的重頭戲：服務(wù)端排查！

2. 服務(wù)端排查

我們的 server 端是一個 Spring MVC 服務(wù)，對于登錄接口來說，它的邏輯如下

@RestController
@RequestMapping(path = "/api/auth", method = RequestMethod.POST)
@Slf4j
public class AuthController {
    @RequestMapping(params = "member.login")
    public ResultTO<TokenDTO> login(@RequestBody UserLoginDTO userLogin) {
        /** 這里寫登錄邏輯 */ 
        return ResultTO.responseSuccess(tokenDTO);
    }
}

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

• 提供性能看板，包括線程、cpu、內(nèi)存等信息，并且會定時的刷新。

• 根據(jù)各種條件查看線程快照。比如找出cpu占用率最高的 n 個線程等

• 輸出jvm的各種信息，如 gc 算法、jdk 版本、ClassPath 等

• 查看/設(shè)置sysprop和sysenv

• 查看某個類的靜態(tài)屬性，也可以通過 ognl 語法執(zhí)行一些語句

• 查看已加載的類的詳細信息，比如這個類從哪個 jar 包加載的。也可以查看類的方法的信息

• dump 某個類的字節(jié)碼到指定目錄

• 直接反編譯指定的類

• 查看類加載器的一些信息

• 可以讓jvm重新加載某個類

• 監(jiān)控方法的執(zhí)行，同時可以獲取到執(zhí)行的入?yún)ⅰ⒊鰠⒁约皰伋龅漠惓?/span>

• 追蹤方法執(zhí)行的調(diào)用棧，以及各個方法的調(diào)用時間

這里我們要用到它的最后一項功能，實時查看各個方法的調(diào)用時間，整個使用 arthas 的步驟如下

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

curl -O https://arthas.aliyun.com/arthas-boot.jar

2、 啟動 arthas，啟動后會展示一個 java 進程列表，我們選中 Arthas 將要調(diào)試的 Spring MVC 進程，以下選中 2，然后即可進入 arthas 的交互式界面（以下 arthas 展示的其實不只這么多信息，過濾了不少描述性的信息，只保留對大家有用的核心信息）

[root@d-sts-sh-1-spring-mvc-service-0 buser]# /opt/java8/bin/java -jar arthas-boot.jar
[INFO] arthas-boot version: 3.5.1
[INFO] Found existing java process, please choose one and input the serial number of the process, eg : 1. Then hit ENTER.
* [1]: 99 org.apache.flume.node.Application
  [2]: 2698 /opt/apps/business/spring-mvc-service.jar
2
[arthas@2698]$

然后我們就可以用 arthas 的 trace 命令來追蹤方法調(diào)用,什么是 trace 命令，官方對其功能的介紹如下：

追蹤方法內(nèi)部調(diào)用路徑，并輸出方法路徑上的每個節(jié)點上耗時，trace 命令能主動搜索 class-pattern／method-pattern 對應(yīng)的方法調(diào)用路徑，渲染和統(tǒng)計整個調(diào)用鏈路上的所有性能開銷和追蹤調(diào)用鏈路。

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

[arthas@2698]$ trace com.xxx.AuthController login

然后在瀏覽器執(zhí)行登錄操作，當瀏覽器登錄時間為 3s+ 時， trace 對應(yīng)的追蹤結(jié)果如下

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

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

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

當瀏覽器的登錄請求為 3s+ 時，再次觀察此次的 trace 結(jié)果：

也不過區(qū)區(qū) 81 ms! 在生產(chǎn)的兩臺機器上都試了多次，結(jié)論為當前端請求為 3s 時，兩臺機器的執(zhí)行時間都為 81 ms 左右！至此可以斷定線上的兩臺機器 SpringMVC 服務(wù)是沒有問題的！既然線上機器服務(wù)沒有問題，那只能從流量的流轉(zhuǎn)路徑著手了，客戶端發(fā)出請求要經(jīng)過哪些流程才能到達 SpringMVC 服務(wù)？

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

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

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

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

有人可能會好奇，運維是怎么查出來的呢，通過 「curl -I www.example」的形式可以輸出開頭信息,然后加上 -b 選項可以帶上 cookie，我們的接入層如果發(fā)現(xiàn)請求里帶有某些特殊的 cookie 會返回一個名為「X-KF-Via」的頭字段，如下

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

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

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

總結(jié)

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

在做 Server 壓力測試時發(fā)現(xiàn)，客戶端給服務(wù)器不斷發(fā)請求，并接受服務(wù)器端的響應(yīng)。發(fā)現(xiàn)接收服務(wù)器響應(yīng)的過程中，會出現(xiàn) recv 服務(wù)器端響應(yīng)，阻塞 40ms 的情況，但是查看 server 端日志，Server 都在 2ms 內(nèi)將請求處理完成，并給客戶端響應(yīng)

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