[[343799]]

背景

你好，我是彤哥。

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

我8點(diǎn)半左右到家，立馬上線入會。

重啟

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

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

升級配置

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

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

有點(diǎn)意思了。

此時，彤哥我介入了。

查看監(jiān)控

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

本地壓測

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

看來，確實(shí)跟服務(wù)本身沒有問題。

代碼走查

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

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

加日志

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

當(dāng)然了，結(jié)果沒有什么變化，分析日志。

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

修改redis連接數(shù)

查看redis配置，用的是單機(jī)模式，1G內(nèi)存， 連接數(shù)默認(rèn)的8，客戶端還是比較老的jedis，果斷改成springboot默認(rèn)的lettuce，連接數(shù)先調(diào)整為50，重啟服務(wù)，壓一波。

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

事實(shí)證明，并沒有明顯地提升。

再次查看日志

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

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

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

很無奈了，此時，已經(jīng)半夜3點(diǎn)多了，領(lǐng)導(dǎo)發(fā)話，把華為云的人喊起來。

華為云排查

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

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

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

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

真的是握了顆草了，這就有點(diǎn)坑了，你限流就算了，帶寬滿了也不報(bào)警一下的么。。

這真是個蛋疼的問題。

到這里，我們以為問題就這樣解決了，領(lǐng)導(dǎo)們也去睡覺了~~

上生產(chǎn)

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

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

從生產(chǎn)提交拉一個hotfix分支，關(guān)閉簽名，重啟服務(wù)，壓測走一波。

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

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

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

真是個蛋疼的問題。

查看監(jiān)控

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

這次不正常的變成了CPU，redis的CPU壓測的時候直接飆到了100%，導(dǎo)到應(yīng)用響應(yīng)緩慢。

再次喚醒華為云redis專家

已經(jīng)凌晨四點(diǎn)多了，大家已經(jīng)沒什么思路了，華為云的redis專家，你給我再起來!

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

萬惡的scan

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

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

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

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

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

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

當(dāng)前解決辦法

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

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

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

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

總結(jié)

本次生產(chǎn)事件跟以往遇到的事件都略有不同，大概總結(jié)一下：

以往都是應(yīng)用服務(wù)本身的CPU、內(nèi)存、磁盤、JVM這些問題，redis的帶寬和限流還是第一次遇見;

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

redis一定要禁用掉keys和scan命令，且大部分key應(yīng)該設(shè)置過期時間!

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

本文轉(zhuǎn)載自微信公眾號「彤哥讀源碼」，可以通過以下二維碼關(guān)注。轉(zhuǎn)載本文請聯(lián)系彤哥讀源碼公眾號。