記一次生產事故:30萬單就這樣沒了!

彤哥讀原始碼發表於2020-09-24

背景

你好,我是彤哥。

昨天晚上下班回家,在地鐵上,老大突然打來電話,B系統生產環境響應緩慢,影響了A系統的使用,幾萬小哥收不了單,大概有30萬單卡住了,你去幫忙定位一下。

我8點半左右到家,立馬上線入會。

重啟

我入會的時候,已經有同事在幫忙定位了,俗話說的好,重啟能解決80%的問題,如果重啟解決不了,那肯定是重啟的次數還不夠,呸,不對,重啟解決不了,就真的要去定位了。

事實證明,重啟後走一波壓測依然沒什麼用,1000個併發,平均響應時間在3~4秒,連續壓了幾次都是這樣的結果。

升級配置

重啟看來是無效了,進入第二個階段——升級配置,2臺4核8G的例項升級到6臺8核16G,資料庫的配置也翻了一倍,能用錢解決的問題,我們一般不會投入太多的人力^^

事實證明,加配置也沒什麼卵用,1000個併發,壓測的平均響應時間還是在3~4秒。

有點意思了。

此時,彤哥我介入了。

檢視監控

我上線之後,檢視了一下監控,例項的CPU、記憶體、磁碟、網路IO、JVM堆記憶體使用情況好像都沒啥問題,這真是個頭疼的問題。

本地壓測

我們分成兩波同學,一波去準備本地壓測,一波繼續分析,經過本地壓測,我們發現,本地環境,單機,1000個併發,妥妥的,毛問題都沒有,平均響應基本維持在幾百毫秒。

看來,確實跟服務本身沒有問題。

程式碼走查

實在沒有辦法了,拿出程式碼,一群大老爺們一起看程式碼,研發同學給我們講解業務邏輯,當然,他已經被各位大佬給罵死了,寫的什麼破程式碼,其實,在彤哥介入之前,他們已經改過一波程式碼了,有個地方把redis命令scan改成了keys *,這裡埋了個坑,但是,現在不是主要問題,後面我們會說。

程式碼一路走讀下來,發現有很多的redis操作,還有個for迴圈裡面在調redis的get命令,其它的都是常規的資料庫操作,而且都加了索引的,所以,初步排查,資料庫這裡應該是沒有什麼問題,主要問題可能還是集中在redis這塊,呼叫太頻繁了。

加日誌

程式碼走查下來,除了那個scan改成了keys *(這個我還不知道),基本上沒有什麼問題,加日誌吧, 一小段一小段的加上日誌,OK,重啟服務,壓測來一波。

當然了,結果沒有什麼變化,分析日誌。

通過日誌,我們發現,呼叫redis的時候時而很快,時而很慢,看起來像是連線池不夠的樣子,也就是一批請求先行,一批請求在等待空閒的redis連線。

修改redis連線數

檢視redis配置,用的是單機模式,1G記憶體, 連線數預設的8,客戶端還是比較老的jedis,果斷改成springboot預設的lettuce,連線數先調整為50,重啟服務,壓一波。

平均響應時間從34秒降到了23秒,並不明顯,繼續加大連線數,因為我們是1000個併發,每個請求都有很多次redis操作,所以,肯定會有等待,這次我們把連線數直接幹到了1000,重啟服務,壓一波。

事實證明,並沒有明顯地提升。

再次檢視日誌

此時,已經沒有什麼好的解決辦法了,我們再次回到日誌中,檢視redis相關操作的時間,發現99%的get操作都是很快返回的,基本上是在05毫秒之間,但是,總有那麼幾個達到了800900毫秒才返回。

我們以為redis這塊沒什麼問題了。

但是,壓測了好幾次,時間一直提不上去。

很無奈了,此時,已經半夜3點多了,領導發話,把華為雲的人喊起來。

華為雲排查

最後,我們把華為雲相關的人員喊起來一起排查問題,當然,他們是不情願的,但是,誰讓我們給錢了呢^^

華為雲的負責人,把redis的專家搞起來,幫我們看了下redis的指標,最後,發現是redis的頻寬滿了,然後觸發了限流機制。

他們臨時把redis的頻寬增大三倍,讓我們再壓測一波。

握了顆草,平均響應時間一下子降到了200~300毫秒!!!!

真的是握了顆草了,這就有點坑了,你限流就算了,頻寬滿了也不報警一下的麼。。

這真是個蛋疼的問題。

到這裡,我們以為問題就這樣解決了,領導們也去睡覺了~~

上生產

既然問題原因找到了,那就上生產壓一波吧~

我們讓華為雲的專家把生產的頻寬也增大了三倍大小。

從生產提交拉一個hotfix分支,關閉簽名,重啟服務,壓測走一波。

完蛋,生產環境更差,平均響應時間在5~6秒。

測試環境我們是改了連線池配置的,生產環境還是jedis,改之,走一波。

並沒有什麼實際作用,還是5~6秒。

真是個蛋疼的問題。

檢視監控

檢視華為雲中redis的監控,這次頻寬、流控都是正常的。

這次不正常的變成了CPU,redis的CPU壓測的時候直接飆到了100%,導到應用響應緩慢。

再次喚醒華為雲redis專家

已經凌晨四點多了,大家已經沒什麼思路了,華為雲的redis專家,你給我再起來!

再次喚醒華為雲的redis專家,幫我們分析了下後臺,發現10分鐘內進行了14萬次scan~~

關注公主號彤哥讀原始碼,檢視更多幹貨好文!

萬惡的scan

詢問研發人員哪裡用到了scan(前面他們改的,我不知道),發現,每次請求都會呼叫scan去拿某個字首開頭的key,每次掃描1000條資料,檢視redis鍵總數,大概有11萬條,也就是說,一個請求就要scan100次,1000併發,大概就是10幾萬次scan,我們知道,redis中scankeys *是要進行全表掃描的,非常消耗CPU,14萬次scan操作,直接讓CPU上天了。

為什麼測試環境CPU沒有上天呢?

對比了下,測試環境和生產環境redis的鍵總數,測試環境只有900個key,每次請求也就scan一次或者keys *一次,毛線問題都沒有。

為什麼生產環境有這麼多key?

詢問研發人員,為什麼生產環境有這麼多key,沒有設定過期時間嗎?

研發人員說設定了的,是另一個同事寫的程式碼,開啟程式碼,真是一段魔性的程式碼,具體程式碼我就不方便貼出來了,裡面有根據條件判斷要不要設定過期時間,經過分析,大部分情況下,都沒有設定過期時間成功。

當前解決辦法

此時,已經凌晨4點半了,雖然大家還很興奮,但是,經過領導決策,暫時先不動了,因為,目前A系統已經暫停呼叫B系統了,所以,此時B系統可以說流量幾乎為0了,我們白天再分兩個階段來修復這個問題。

第一步,先清理掉生產環境redis的資料,只保留一小部分必要的資料。

第二步,修改scan某字首開頭的資料,改成hash儲存,這樣可以減少掃描的範圍。

好了,本次生產事故排查就到這裡了,後續,彤哥,也會繼續跟進的。

總結

本次生產事件跟以往遇到的事件都略有不同,大概總結一下:

  1. 以往都是應用服務本身的CPU、記憶體、磁碟、JVM這些問題,redis的頻寬和限流還是第一次遇見;
  2. 上了華為雲以後,很多東西還沒有弄得熟練,包括監控指標這些,還需要慢慢摸索;
  3. redis一定要禁用掉keys和scan命令,且大部分key應該設定過期時間!

好了,本次事件大概就寫這麼多,後續有新的情況彤哥也會繼續跟進的,當然,最好不要有新的情況^^

相關文章