摘要：究竟是不是cpu占比高的問題導致redis超時的呢？ 本文分享自華為雲社區《我又和redis超時杠上了》，作者：藍胖子的編程夢 。 背景 經過上次redis超時排查，並聯繫雲服務商解決之後，redis超時的現象好了一陣子，但是最近又有超時現象報出，但與上次不同的是，這次超時的現象發生在業務高峰 ...
摘要：究竟是不是cpu占比高的問題導致redis超時的呢？
本文分享自華為雲社區《我又和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的確比較高了，但是究竟是不是客戶端問題呢？我又抓包論證了的確是客戶端問題，那究竟是不是協程調度問題呢？我又列出協程調度延遲。
