解 Bug 之路 - 記一次線上請求偶爾變慢的排查

前言

最近解決了個比較棘手的問題，由於排查過程挺有意思，於是就以此爲素材寫出了本篇文章。

Bug 現場

這是一個偶發的性能問題。在每天幾百萬比交易請求中，平均耗時大約爲 300ms，但總有那麼 100 多筆會超過 1s，讓我們業務耗時監控的 99.99 線變得很尷尬。如下圖所示:

爲了精益求精, 更爲了消除這個尷尬的指標，筆者開始探尋起這 100 多慢請求筆的原因。

先找一筆看看

由於筆者寫的框架預留了 traceId, 所以找到這筆請求的整個調用的鏈路還是非常簡單的。而且通過框架中的攔截器在性能日誌中算出了每一筆請求的耗時。這樣，非常便於分析鏈路到底是在哪邊耗時了。性能日誌中的某個例子如下圖所示:

2020-09-01 15:06:59.010 [abcdefg,A->B,Dubbo-thread-1,ipA->ipB] B.facade,cost 10 ms

拉出來一整條調用鏈路後，發現最前面的 B 系統調用 C 系統就比較慢。後面鏈路還有幾個調用慢的，那先不管三七二十一，先分析 B 調用 C 系統吧。

我們從監控系統看出來正常的 B 系統調用 C 系統平均耗時只有 20ms, 這次的耗時增長了 10 倍！
正常思路，那當然是 C 系統有問題麼，畢竟慢了 10 倍！去 C 系統的性能日誌裏面看看,

2020-09-01 15:06:59.210 [abcdefg,B->C,Dubbo-thread-1,ipB->ipC] C.facade,cost 20 ms

啪啪啪打臉，竟然只有 20ms, 和平均耗時差不多。難道問題在網絡上? B 到 C 之間由於丟包重傳所以到了 200ms?

甩給網絡？

由於筆者對 TCP 協議還是比較瞭解的，tcp 第一次丟包重傳是 200ms，那麼加上 C 處理的時間 20ms, 即 220ms 必須得大於 200ms。而由於 Nagle 和 DelayAck 造成的 tcp 延遲也僅僅是 40ms, 兩者相加 60ms 遠遠小於 200ms, 所以這個 200ms 是丟包或者 DelayAck 的概率不大。
本着萬一呢的態度, 畢竟下絕對的判斷往往會被打臉，看了下我們的監控系統，發現當時流量距離網卡容量只有 1/10 左右，距離打滿網卡還有非常遠的距離。
注意，這個監控的是由 KVM 虛擬機虛擬出來的網卡。看了這個流量，筆者感覺網絡上問題的概率不大。

GC 了？

筆者第二個想到的是 GC 了，但是觀察了 B 和 C 的當時時刻的 GC 日誌，非常正常，沒有 FullGC，youngGC 也在毫秒級，完全不會有 200ms 這麼長。TCP 重傳 + 雙方都 youngGC? 這個也太巧了點吧，也不是不可用。不過詳細的計算了時間點，並納入了雙方機器的時鐘誤差後，發現基本不可能。

再看看其它幾筆

盡然這個問題每天有 100 多筆 (當然了，也不排除其中混雜了其它不同的問題), 那麼就試試看看其它幾筆，有沒有什麼共性。這一看，發現個奇怪的現象，就是有時候是 A 調用 B 慢，有時候是 B 調用 C 慢，還有時候是 E 調用 F 慢。他們唯一的共性就是耗時變長了，但是這個耗時增加的比例有 5 倍的，有 10 倍的，完全沒有規律可循。
這不禁讓筆者陷入了沉思。

尋找突破點

既然通用規律只有變慢，暫時無法進一步挖掘。那麼還是去 B 系統上去看看情況吧，去對應 B 系統上故意不用 grep 而是用 less 看了下，上下掃了兩眼。突然發現，貌似緊鄰着的幾條請求都很慢，而且是無差別變慢！也就是說 B 系統調用任何系統在這個時間點都有好幾倍甚至十幾倍的耗時！
終於找到了一個突破點，B 系統本身或者其所屬的環境應該有問題！於是筆者用 awk 統計了下 B 系統這個小時內每分鐘的平均調用時長，用了下面這條命令:

cat 性能日誌 | grep '時間點 | awk -F ' ' '{print $2, $5}' |.......| awk -F ' ' '{sum[$1]+=$3;count[$1]+=1}END{for(i in sum) {print i,sum[i]/count[i]}}'

發現

15:00 20
15:01 21
15:02 15
15:03 30
.......
15:06 172.4
15:07 252.4
15:08 181.4
15:10 20
15:10 21
15:10 22

在 15:06-15:08 這三分鐘之內，調用時間會暴漲！但奇怪的是 B 系統明明有幾十臺機器，只有這一臺在這個時間段內會暴漲。難道這個時間有定時任務？筆者搜索了下 B 系統昨天的日誌，發現在同樣的時間段內，還是暴漲了！再接着搜索其它調用慢的，例如 E->F, 發現他們也在 15:06-15:08 報錯！於是筆者，一橫心，直接用 awk 算出了所有系統間調用慢機器白天內的所有分鐘平均耗時 (晚上的流量小不計入內), 發現:
所有調用慢的機器，都非常巧的在每個小時 06-08 分鐘之內調用慢。再觀察下慢的請求，發現他們也全部是分佈在不同小時的 06-08 分時間段內！

定時任務?

第一反應是有定時任務，查了下所有調用機器的 crontab 沒有問題。問了下對應的開發有沒有調度，沒有調度，而且那個時間段由於耗時的原因，每秒請求數反而變小了。翻了下機器監控，也都挺正常。思維陷入了僵局，突然筆者靈光一閃，我們的應用全部是在 KVM 虛擬機上，會不會是宿主機出了問題。於是聯繫了下 SA, 看看這些機器的宿主機是個什麼情況。

每個變慢的機器的宿主機都有 Redis!

這一看就發現規律了，原來變慢的機器上都和 Redis 共宿主機！
登陸上對應的 Redis 服務器，發現 CPU 果然在那個時間點有尖峯。而這點尖峯對整個宿主機的 CPU 毫無影響 (畢竟宿主機有 64 個核)。crontab -l 一下，果然有定時任務，腳本名爲 Backup! 它起始時間點就是從 06 分開始往 GlusterFS 盤進行備份，從 06 分開始 CPU 使用率開始上升 =>07 分達到頂峯 =>08 分降下來，和耗時曲線完全一致！
原來 Redis 往 Gluster 盤備份佔據了大量的 IO 操作，所以導致宿主機上的其它應用做 IO 操作時會變得很慢，進而導致但凡是這個備份時間內系統間調用的平均耗時都會暴漲接近 10 倍，最終導致了高耗時的請求。

爲什麼調用請求超時 1s 的概率這麼低

由於我們線上每個應用都有幾十臺機器，而基本每次調用只有幾十毫秒。所以只有這個請求連續落到三個甚至多個和 Redis 共宿主機的系統裏面纔會導致請求超過 1s，這樣才能被我們的統計腳本監測到，而那些大量的正常請求完全拉平了平均值。

解決方案

我們將線上實時鏈路的系統從對應有 Redis 的宿主機中遷移出來，再也沒有那個尷尬的 1s 了。

藉此推薦一本書。

這本書豆瓣評價 8.6 分，在詳細講解性能問題排查的同時補充了大量的基礎知識，是本很不錯的書。

總結

在遇到問題，並且思路陷入僵局時，可以通過一些腳本工具，例如 grep 以及 awk 或者其它一些工具對衆多日誌進行分析，不停的去尋找規律，從無序中找到有序，往往能夠產生意想不到的效果！歡迎大家加我公衆號，裏面有各種乾貨，還有大禮包相送哦!

本文由 Readfog 進行 AMP 轉碼，版權歸原作者所有。
來源：https://mp.weixin.qq.com/s/pILItJ4fx-sCFA4pf34qLw