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

解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了。

總結

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