[[343799]]

背景

你好，我是彤哥。

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

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

重啟

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

事實證明，重啟后走一波壓測依然沒什么用，1000個并發(fā)，平均響應時間在3~4秒，連續(xù)壓了幾次都是這樣的結果。

升級配置

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

事實證明，加配置也沒什么卵用，1000個并發(fā)，壓測的平均響應時間還是在3~4秒。

有點意思了。

此時，彤哥我介入了。

查看監(jiān)控

我上線之后，查看了一下監(jiān)控，實例的CPU、內存、磁盤、網絡IO、JVM堆內存使用情況好像都沒啥問題，這真是個頭疼的問題。

本地壓測

我們分成兩波同學，一波去準備本地壓測，一波繼續(xù)分析，經過本地壓測，我們發(fā)現，本地環(huán)境，單機，1000個并發(fā)，妥妥的，毛問題都沒有，平均響應基本維持在幾百毫秒。

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

代碼走查

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

代碼一路走讀下來，發(fā)現有很多的redis操作，還有個for循環(huán)里面在調redis的get命令，其它的都是常規(guī)的數據庫操作，而且都加了索引的，所以，初步排查，數據庫這里應該是沒有什么問題，主要問題可能還是集中在redis這塊，調用太頻繁了。

加日志

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

當然了，結果沒有什么變化，分析日志。

通過日志，我們發(fā)現，調用redis的時候時而很快，時而很慢，看起來像是連接池不夠的樣子，也就是一批請求先行，一批請求在等待空閑的redis連接。

修改redis連接數

查看redis配置，用的是單機模式，1G內存， 連接數默認的8，客戶端還是比較老的jedis，果斷改成springboot默認的lettuce，連接數先調整為50，重啟服務，壓一波。

平均響應時間從3~4秒降到了2~3秒，并不明顯，繼續(xù)加大連接數，因為我們是1000個并發(fā)，每個請求都有很多次redis操作，所以，肯定會有等待，這次我們把連接數直接干到了1000，重啟服務，壓一波。

事實證明，并沒有明顯地提升。

再次查看日志

此時，已經沒有什么好的解決辦法了，我們再次回到日志中，查看redis相關操作的時間，發(fā)現99%的get操作都是很快返回的，基本上是在0~5毫秒之間，但是，總有那么幾個達到了800~900毫秒才返回。

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

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

很無奈了，此時，已經半夜3點多了，領導發(fā)話，把華為云的人喊起來。

華為云排查

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

華為云的負責人，把redis的專家搞起來，幫我們看了下redis的指標，最后，發(fā)現是redis的帶寬滿了，然后觸發(fā)了限流機制。

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

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

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

這真是個蛋疼的問題。

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

上生產

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

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

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

完蛋，生產環(huán)境更差，平均響應時間在5~6秒。

測試環(huán)境我們是改了連接池配置的，生產環(huán)境還是jedis，改之，走一波。

并沒有什么實際作用，還是5~6秒。

真是個蛋疼的問題。

查看監(jiān)控

查看華為云中redis的監(jiān)控，這次帶寬、流控都是正常的。

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

再次喚醒華為云redis專家

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

再次喚醒華為云的redis專家，幫我們分析了下后臺，發(fā)現10分鐘內進行了14萬次scan~~

萬惡的scan

詢問研發(fā)人員哪里用到了scan(前面他們改的，我不知道)，發(fā)現，每次請求都會調用scan去拿某個前綴開頭的key，每次掃描1000條數據，查看redis鍵總數，大概有11萬條，也就是說，一個請求就要scan100次，1000并發(fā)，大概就是10幾萬次scan，我們知道，redis中scan和keys *是要進行全表掃描的，非常消耗CPU，14萬次scan操作，直接讓CPU上天了。

為什么測試環(huán)境CPU沒有上天呢?

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

為什么生產環(huán)境有這么多key?

詢問研發(fā)人員，為什么生產環(huán)境有這么多key，沒有設置過期時間嗎?

研發(fā)人員說設置了的，是另一個同事寫的代碼，打開代碼，真是一段魔性的代碼，具體代碼我就不方便貼出來了，里面有根據條件判斷要不要設置過期時間，經過分析，大部分情況下，都沒有設置過期時間成功。

當前解決辦法

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

第一步，先清理掉生產環(huán)境redis的數據，只保留一小部分必要的數據。

第二步，修改scan某前綴開頭的數據，改成hash存儲，這樣可以減少掃描的范圍。

好了，本次生產事故排查就到這里了，后續(xù)，彤哥，也會繼續(xù)跟進的。

總結

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

以往都是應用服務本身的CPU、內存、磁盤、JVM這些問題，redis的帶寬和限流還是第一次遇見;

上了華為云以后，很多東西還沒有弄得熟練，包括監(jiān)控指標這些，還需要慢慢摸索;

redis一定要禁用掉keys和scan命令，且大部分key應該設置過期時間!

好了，本次事件大概就寫這么多，后續(xù)有新的情況彤哥也會繼續(xù)跟進的，當然，最好不要有新的情況^^

本文轉載自微信公眾號「彤哥讀源碼」，可以通過以下二維碼關注。轉載本文請聯系彤哥讀源碼公眾號。