我又和redis超時槓上了

背景

經過上次redis超時排查，並聯絡雲服務商解決之後，redis超時的現象好了一陣子，但是最近又有超時現象報出，但與上次不同的是，這次超時的現象發生在業務高峰期，在簡單看過伺服器的各項指標以後，發現只有cpu的使用率在高峰期略高，我們是8核cpu，高峰期能達到90%的使用率，其餘指標都相對正常。

但究竟是不是cpu佔比高的問題導致redis超時的呢？還有待商榷，因為cpu排程程式慢本質上也是個概率性事件。

解決思路

略帶僥倖的聯絡雲服務商

有了上次的經驗過後，我也是聯絡了雲服務商那邊也排查下是否還存在上次超時的原因，但其實還是有直覺，這次的原因和上次超時是不一樣的（備註：上次超時是由於雲服務商那邊對叢集的流量隔離做的不夠好，導致其他企業機器流量影響到了我們的機器，且發生在業務低峰期），這次發生在業務高峰期。

果然，雲服務商得出的結論也是之前出問題的機器以及遷移走了，並且他們也和我同時展開排查。

抓包分析

在ecs伺服器上進行抓包，當出現超時時，關閉tcpdump進行分析。

tcpdump 漏包了？

在dump下抓包檔案後，經過wireshark分析，並沒有發現丟包資訊，想著應該是tcpdump漏包了。

tcpdump 出現漏包的情況

[webserver@hw-sg1-test-0001 ~]$ sudo tcpdump -i eth0 tcp  port 6379   -w p.cap -W 2 -G 3600 -C 2000
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 262144 bytes

可以看到預設的抓包大小262144 bytes，在業務高峰期如果每個包最大長度都在這個值，很可能就導致緩衝區滿了，而之前一次抓包分析為什麼就沒有這個問題呢，因為那是在業務低峰期，tcpdump丟包概率比較小。

sudo tcpdump -i eth0 tcp  port 6379   -w p5.cap -W 2 -G 3600 -C 2000
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 262144 bytes
^C147940 packets captured
468554 packets received by filter
318544 packets dropped by kernel

packets dropped by kernel 說明tcpdump丟棄了某些包，因為tcpdump在處理包時，是先將包放到一個緩衝區進行分析，當緩衝區滿的時候會直接進行丟棄，這樣導致我在用wireshark分析包的時候，就會出現有些包找不到的情況。

在縮小抓取的包大小和去掉域名解析後，不再漏包了。

[webserver@hw-sg1-backend-0003 ~]$ sudo tcpdump -i eth0 tcp  port 6379   -w p5.cap -W 2 -G 3600 -C 2000 -n -s 1520
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 1520 bytes
^C21334 packets captured
21454 packets received by filter
0 packets dropped by kernel

抓包分析超時情況

redis使用者端超時時間設定的200ms，可以看到2894687號包是redis伺服器傳送給使用者端的包，然後2897927是使用者端傳送給redis伺服器端的rst，正常情況使用者端收到redis伺服器端的psh訊號的包應該會回覆一個ack的，但是使用者端卻在200ms以後回覆了一個rst，說明了什麼問題？

我們的使用者端是golang寫的，可以想到的情況是，使用者端程式在讀取包過程協程會有切換上下文操作，當用戶端發現有可讀包時並切回go協程的時候，會首先判斷當前讀操作是否超時，如果超時，則直接呼叫close方法關閉連線了。

那麼close方法是傳送rst訊號嗎，正常不應該是fin訊號？
非也，close方法如果關閉的時候，連線讀緩衝區的資料還有未被應用程式讀取的話，那麼此時close方法的呼叫會傳送rst訊號。

可見，問題的確是出在使用者端了，並且看上去像是使用者端來不及讀取伺服器端的訊息。看到這裡，其實我心裡已經百分之八九十確定是cpu的使用率達到瓶頸了。

雲服務商來信了

在分析到上一個步驟的時候，雲服務商告訴我，他們知道原因了，是ecs服務的磁碟吞吐量達到瞬時上線，說故障點是和超時的故障點是吻合的。

我知道這個後，第一時間的疑惑是，為啥磁碟吞吐會影響到網路傳輸，雲服務商給的解釋是磁碟吞吐達到瞬時上線後，對服務整體是有影響的，我又看了下ecs的監控圖示，發現監控圖示顯示的磁碟吞吐遠遠沒有云服務商提到的那麼多。

儘管雲服務商堅持是磁碟iops達到了上限，但還是不能說服我磁碟的iops瞬時上限會那麼大影響到網路傳輸。

於是有了接下來第二天的抓包分析。

第二天的抓包分析

基於對昨天的分析，我懷疑到了cpu頭上，如果cpu切換程序緩慢，協程排程緩慢，那麼的確是有可能發生超時的。由於目前的監控缺少對協程排程延遲的監控，所以決定加上這一指標。

golang1.17後 runtime包提供了協程排程延遲的直方圖統計資訊,而go prometheus的client其實以已經支援將這個資訊轉換為prometheus內建的指標型別，metric名稱是go_sched_latencies_seconds，而我們之前試用prometheus的client包註冊的collector 是相容到go1.16以及之前的版本，所以沒有當改用到最新的collector後，client如期返回了go_sched_latencies_seconds 直方圖資訊。

將這個資訊展示在grafana裡。於是有了第二天協程排程延遲的資訊。p999在業務高峰期間達到了100ms，也是與超時時間吻合的。協程排程延遲指的是協程變為可執行狀態後到被真正執行這段時間等待被排程的時間，這裡都高達100ms了，如果加上cpu執行緒，程序切換上下文時間，很有可能是超過了redis client端設定的200ms超時上限。

為了排除掉是磁碟原因引起的超時。
我在7點又進行了抓包分析，發現和昨天抓到包的情況是一致的，使用者端最後來不及迴應伺服器端的包最後傳送rst了。

然後看了下此時機器磁碟吞吐情況，發現圖中箭頭處也處於高峰期，但是磁碟吞吐量並未上去，而升上去的點正是抓包帶來的，懷疑是抓包寫入檔案導致磁碟吞吐量漲上去了。於是又問了服務商要磁碟達到瞬時峰值的紀錄檔。

發現報瞬時峰值的紀錄檔也和抓包時間吻合，所以已經確認磁碟吞吐達到上限是抓包導致的，網路超時是和磁碟吞吐無關的，反而應該是cpu使用率達到上限了，雖然沒有100%，也是8核，但畢竟cpu某個核達到上限是概率性事件，而對於redis這種時延敏感性應用，一但發生，那麼超時是有可能的。

完美解決

於是，在業務低峰期將我們三臺ecs服務進行了cpu設定提升，提升後效果很明顯，超時在高峰期不見了，協程排程延遲也大大減少。

總結

1，對於抓包分析，還是疏忽了，加上包限制大小，能很好的防止tcpdump抓包時丟包的情況。
2，對於任何第三方的說法要有自己的判斷力，像這次如果中途去將磁碟擴容顯然是不能解決問題的。
3，效能問題分析真是像一個偵探破案的過程，不斷列出證據，不斷排除掉干擾因素，不斷論證的過程也是效能分析的魅力所在吧，就像這次看到cpu的確比較高了，但是究竟是不是使用者端問題呢？我又抓包論證了的確是使用者端問題，那究竟是不是協程排程問題呢？我又列出協程排程延遲。