[[385025]]

圖片來自 Pexels

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

重啟

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

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

升級配置

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

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

有點(diǎn)意思，此時，我介入了。

查看監(jiān)控

我上線之后，查看了一下監(jiān)控，實例的 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)基本維持在幾百毫秒。

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

代碼走查

實在沒有辦法了，拿出代碼，一群大老爺們一起看代碼，研發(fā)同學(xué)給我們講解業(yè)務(wù)邏輯，當(dāng)然，他已經(jīng)被各位大佬給罵死了，寫的什么破代碼。

其實，在我介入之前，他們已經(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ù)，因為我們是 1000 個并發(fā)，每個請求都有很多次 redis 操作，所以，肯定會有等待，這次我們把連接數(shù)直接干到了 1000，重啟服務(wù)，壓一波。

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

再次查看日志

此時，已經(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ā)話，把 XX 云的人喊起來。

云排查

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

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

他們臨時把 redis 的帶寬增大三倍，讓我們再壓測一波。握了顆草，平均響應(yīng)時間一下子降到了 200~300 毫秒!!!!

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

這真是個蛋疼的問題。到這里，我們以為問題就這樣解決了，領(lǐng)導(dǎo)們也去睡覺了!

上生產(chǎn)

既然問題原因找到了，那就上生產(chǎn)壓一波吧!我們讓 XX 云的專家把生產(chǎn)的帶寬也增大了三倍大小。

從生產(chǎn)提交拉一個 hotfix 分支，關(guān)閉簽名，重啟服務(wù)，壓測走一波。完蛋，生產(chǎn)環(huán)境更差，平均響應(yīng)時間在 5~6 秒。

測試環(huán)境我們是改了連接池配置的，生產(chǎn)環(huán)境還是 jedis，改之，走一波。并沒有什么實際作用，還是 5~6 秒。

真是個蛋疼的問題。

查看監(jiān)控

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

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

再次喚醒 XX 云 redis 專家

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

再次喚醒 XX 云的 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 萬條。

也就是說，一個請求就要 scan 100 次，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)決策，暫時先不動了。

因為，目前 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)事故排查就到這里了。

總結(jié)

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

• 以往都是應(yīng)用服務(wù)本身的 CPU、內(nèi)存、磁盤、JVM 這些問題，redis 的帶寬和限流還是第一次遇見。
• 上了 XX 云以后，很多東西還沒有弄得熟練，包括監(jiān)控指標(biāo)這些，還需要慢慢摸索。
• redis 一定要禁用掉 keys 和 scan 命令，且大部分 key 應(yīng)該設(shè)置過期時間!

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

作者：彤哥

編輯：陶家龍

出處：轉(zhuǎn)載自公眾號彤哥讀源碼