【51CTO.com原創(chuàng)稿件】筆者所在的公司有一款大 DAU(日活)的休閑游戲。這款游戲的后端架構(gòu)很簡單，可以簡單理解為通訊-邏輯-存儲三層結(jié)構(gòu)。其中存儲層大量使用了 Redis 和 MySQL。

[[316156]]

圖片來自 Pexels

隨著存量用戶的增加，Redis 就隔三差五的出現(xiàn)問題。所以筆者打算把遇到的一系列問題以及在項目里的實踐都整理記錄下來。

項目組每天 14 點都會遭遇驚魂時刻。一條條告警短信把工程師從午后小憩中拉回現(xiàn)實，之后問題又神秘消失。

是 PM 喊你上工了?還是服務(wù)器給你開玩笑?下面請看工程師如何一步一步揪出真兇，解決問題。

1、起因

某天下午，后端組的監(jiān)控系統(tǒng)發(fā)出告警，服務(wù)器響應(yīng)時間變長，超過了閾值。過一會兒系統(tǒng)自動恢復(fù)了，告警解除。

第二天差不多的時間點，監(jiān)控系統(tǒng)又發(fā)出了同樣的告警，過幾分鐘后又恢復(fù)了。于是我們決定排查這個問題。

2、背景

首先要介紹一下應(yīng)用的架構(gòu)，是很簡單的三層架構(gòu)的 Web 服務(wù)，從外到內(nèi)大概是這樣的：

• Load Balance：對外提供訪問入口，對內(nèi)實現(xiàn)負(fù)載均衡。
• Nginx：放在 LB 后面，實現(xiàn)流控等功能。
• App Service：邏輯服務(wù)，多機(jī)多進(jìn)程。
• Storage：MySQL 和 Redis 組成的存儲層。

我們的服務(wù)部署在 AWS 云上，架構(gòu)里用到了很多 AWS 的服務(wù)，比如 ELB，EC2，RDS 等。

3、表象

排查問題的第一步就是要收集信息。從監(jiān)控和日志系統(tǒng)里提取大量的相關(guān)信息，然后再分析、解決問題。

我們收集到的信息大概是這樣的，在每天 14 點的時候：

• QPS 突增。
• P99 指標(biāo)升高。
• App 服務(wù)器集群 CPU、內(nèi)存都升高，TCP 連接數(shù)暴漲，入網(wǎng)流量降低。
• MySQL Write IOPS 升高，寫入延時升高，數(shù)據(jù)庫連接數(shù)升高。

幾分鐘后，這些指標(biāo)都回歸到正常水平。

4、排查

首先從代碼入手，看看是不是有這個時間點的定時任務(wù)。結(jié)果發(fā)現(xiàn)并沒有。然后就是第一個懷疑對象 MySQL。

使用 mysqlbinlog 命令統(tǒng)計一下各個時間點的 binlog 數(shù)量：

 

我們又在第二天的這個時間點觀察了一下現(xiàn)場，使用 show processlist 命令抓取一下當(dāng)時 MySQL 連接的狀態(tài)，結(jié)果發(fā)現(xiàn)來自 App 服務(wù)器的連接竟然都 sleep 了 20 秒左右，什么事兒都沒做。

初步推論

根據(jù)以上的數(shù)據(jù)可以還原一下當(dāng)時的場景：

• App 服務(wù)器 Socket 數(shù)激增。
• App 服務(wù)器不再進(jìn)行邏輯處理(這個待確認(rèn))。
• App 服務(wù)器不再進(jìn)行任何數(shù)據(jù)庫操作。
• App 服務(wù)器恢復(fù)讀寫數(shù)據(jù)庫。
• 積壓了大量的網(wǎng)絡(luò)請求讓游戲服務(wù)器 CPU 增加。
• 大批量的寫請求涌向數(shù)據(jù)庫造成數(shù)據(jù)庫各項指標(biāo)升高。

那么問題來了：

• 激增的 Socket 來自哪里?
• 或者去連接了誰?
• App 服務(wù)器為什么會長達(dá) 20 秒沒有什么數(shù)據(jù)庫操作?
• App 服務(wù)器是真的 hang 住了?

帶著疑問開始進(jìn)一步排查。

5、深入排查

先解決第一個問題：多出來的 Socket 來自哪里?

App Service

在 14 點前，選一臺 App 服務(wù)器，抓取它的 TCP 連接：

#!/bin/bash 
while [ true ]; do 
    currentHour=$(date +%H) 
    currentMin=$(date +%M) 
    filename=$(date +%y%m%d%H%M%S).txt 
    if [ $currentHour -eq 05 ] && [ $currentMin -gt 58 ];   then 
        ss -t -a >> $filename 
        #/bin/date >> $filename 
 
    elif [ $currentHour -eq 06 ] && [ $currentMin -lt 05 ]; then 
        ss -t -a >> $filename 
        #/bin/date >> $filename 
    elif [ $currentHour -ge 06 ] && [ $currentMin -gt 05 ]; then 
        exit; 
    fi  
    /bin/sleep 1 
done 

對大小差異比較大的文件進(jìn)行比對，發(fā)現(xiàn)多出來的連接來自 Nginx。Nginx 只是個代理，那就排查它的上游 Load Balance。

Load Balance

Load Balance 我們使用的是 AWS 的經(jīng)典產(chǎn)品 ELB。ELB 的日志很大，主要是分析一下這段時間內(nèi)有沒有異常的流量。

經(jīng)過對比分析 13:55-14:00 和 14:00-14:05 這兩個時間段的請求上沒有明顯的差異。

基本上都是由以下請求構(gòu)成：

• https://xxxxxxx.xxxx.xxx:443/time
• https://xxxxx.xxxx.xxx:443/gateway/v1

但是從 14:00:53 開始，帶 gateway 的請求大部分都返回 504，帶 time 的請求都正常返回。504 表示網(wǎng)關(guān)超時，就是 App 響應(yīng)超時了。

根據(jù)這個信息又可以推斷出一些情況：

• App Service 還在正常提供服務(wù)，否則 time 請求不會正常返回。
• App Service 所有寫數(shù)據(jù)庫的操作都處于等待的狀態(tài)。
• Nginx 到 App Service 的連接得不到及時處理，所以連接很長時間沒有斷開，導(dǎo)致了 Nginx 和 App Service 的 Socket 連接快速增長。

根據(jù)以上，基本上可以排除是 ELB，Nginx 帶來的問題。那么問題就剩下一個，什么數(shù)據(jù)庫長時間不可寫呢? 而且每天都在固定時間。

MySQL

問題又回到了數(shù)據(jù)庫上，首先想到的就是備份，但是我們的備份時間不在出問題的時間段。

我們使用的是 AWS 的 RDS 服務(wù)，查閱了一下 RDS 關(guān)于備份的文檔。只有在數(shù)據(jù)庫備份的時候才可能會出現(xiàn)寫 I/O 掛起，導(dǎo)致數(shù)據(jù)庫不可寫。

而默認(rèn)的備份時間窗口是這樣的：

這個開始的時間也剛好在我們出問題的時間，簡直是太巧合了。

下一步就是要確認(rèn)這個問題。是在偷偷的幫我們做備份，還是實例所在的物理機(jī)上的其他實例干擾了我們?

在某個 MySQL 實例上建個新的數(shù)據(jù)庫 test，創(chuàng)建一張新表 test：

CREATE TABLE `test` ( 
    `id` int(10) unsigned NOT NULL AUTO_INCREMENT, 
    `curdate` varchar(100) NOT NULL, 
    PRIMARY KEY (`id`) 
) ENGINE=InnoDB AUTO_INCREMENT=2 DEFAULT CHARSET=utf8; 

每秒鐘往這張表里寫條數(shù)據(jù)，數(shù)據(jù)的內(nèi)容是當(dāng)前時間，這樣就能看出來在哪個時間段數(shù)據(jù)庫不可寫了。

同時每秒鐘讀取這張表的最大值，記錄下結(jié)果和當(dāng)前時間，這樣就能看出來哪個時間段數(shù)據(jù)庫不可讀。

測試的腳本如下：

#!/bin/bash 
host=xxxx.xxx.xxx 
port=3306 
user=xxxxx 
password=xxxxx 
 
mysql="mysql -u$user -p$password -h$host -P$port --default-character-set=utf8 -A -N" 
 
fetchsql="show processlist;" 
selectsql="select max(id),now(3) from test.test;" 
insertsql="insert into test.test(curdate) value(now(3));" 
 
function run(){ 
    filename_prefix=$1 
    mysqlcmd="$($mysql -e "$fetchsql")" 
    echo $mysqlcmd >> $filename_prefix.procs.txt 
    mysqlcmd="$($mysql -e "$selectsql")" 
    echo $mysqlcmd >> $filename_prefix.select.txt    
    mysqlcmd="$($mysql -e "$insertsql" )"    
} 
while [ true ]; do 
    currentHour=$(date +%H) 
    currentMin=$(date +%M) 
    filename_prefix=./checksql/$(date +%y%m%d%H%M%S) 
    $(run $filename_prefix) 
    if [ $currentHour -eq 05 ] && [ $currentMin -gt 59 ];   then 
        $(run $filename_prefix); 
 
    elif [ $currentHour -eq 06 ] && [ $currentMin -lt 02 ]; then 
        $(run $filename_prefix); 
 
    elif [ $currentHour -ge 06 ] && [ $currentMin -gt 02 ]; then 
        exit; 
    fi 
 
    /bin/sleep 1 
 
done 

這個腳本同時還每秒鐘掃描一次 MySQL 各個客戶端的工作狀態(tài)。最后得到的結(jié)論是，出現(xiàn)問題的時間點，數(shù)據(jù)庫可讀也可寫。

問題好像陷入了困境。懷疑的點被一一證明沒有問題。線索也斷了。只能再回到起點了，繼續(xù)從代碼下手，看看哪里會造成單點，哪里出現(xiàn)了問題會讓所有的游戲服務(wù)器集體卡住，或者是讓數(shù)據(jù)庫操作卡住。

Redis

終于排查到了罪魁禍?zhǔn)字鹘?，最可疑的有兩個點：

• 數(shù)據(jù)庫分片的方案依賴 Redis。Redis 里存儲了每個用戶的數(shù)據(jù)庫分片 id，用來查找其數(shù)據(jù)所在的位置。
• 用戶的設(shè)備和邏輯 id 的映射關(guān)系，也存儲在 Redis 里。幾乎每個 API 請求都要查找這個映射關(guān)系。

以上兩點幾乎是一個 API 請求的開始，如果這兩點出現(xiàn)了問題，后續(xù)的操作都會被卡住。

經(jīng)過和 OPS 確認(rèn)，這兩個 Redis 的備份時間窗口確實在 6:00-7:00utc。而且備份都是在從庫上進(jìn)行的，我們程序里的讀操作也是在從庫上進(jìn)行的。

通過 Redis 的 info 命令，參考 Redis 最近一次的備份時間，時間點也剛好都在北京時間 14:01 左右。

進(jìn)一步確認(rèn)嫌疑：把兩個 Redis 的備份時間做出更改。Redis1 更換為 3:00-4:00utc，Redis2 更換為 7:00-8:00utc。

北京時間 11:00 左右 Redis1 正常備份，問題沒有復(fù)現(xiàn);北京時間 14:00 左右問題沒有復(fù)現(xiàn);北京時間 15:00 左右 Redis2 正常備份，問題復(fù)現(xiàn)。

事后查看了一下 Redis1 和 Redis2 的數(shù)據(jù)量，Redis2 是 Redis1 的 5 倍左右。

Redis1 占用內(nèi)存 1.3G 左右，Redis2 占用內(nèi)存 6.0G 左右。Redis1 的備份過程幾乎在瞬間完成，對 App 的影響不明顯。

6、結(jié)論

問題出現(xiàn)的大致過程是這樣的：

• Redis2 在北京時間的 14 點左右進(jìn)行了從庫備份。
• 備份期間導(dǎo)致了整個 Reids 從庫的讀取操作被阻塞住。
• 進(jìn)一步導(dǎo)致了用戶的 API 請求被阻塞住。
• 這期間沒有進(jìn)行任何數(shù)據(jù)庫的操作。
• 被逐漸積累的 API 請求，在備份完成的一小段時間內(nèi)，給 Nginx，App Service，Redis，RDS 都帶來了不小的沖擊。
• 所以出現(xiàn)了前文中描述的現(xiàn)象。

7、事后煙

其實問題的根源還在 Redis 的備份上，我們就來聊一下 Redis 的備份。

Redis 的持久化可以分為兩種方案：

• 全量方式 RDB
• 增量方式 AOF

詳情可以參考官方中文翻譯：

http://www.redis.cn/topics/persistence.html

RDB

把內(nèi)存中的全部數(shù)據(jù)按格式寫入備份文件，這就是全量備份。它又分為兩種不同的形式。

涉及到的 Redis 命令是 SAVE/BGSAVE：

• SAVE：眾所周知，Redis 服務(wù)都是單線程的。SAVE 和其他常見的命令一樣，也是運行在主進(jìn)程里的?？上攵?，如果 SAVE 的動作很慢，其他命令都得排隊等著它結(jié)束。
• BGSAVE：BGSAVE 命令也可以觸發(fā)全量備份，但是 Redis 會為它 Fork 出來一個子進(jìn)程，BGSAVE 命令運行在子進(jìn)程里，它不會影響到 Redis 的主進(jìn)程執(zhí)行其他指令。它唯一的影響可能就是會在操作系統(tǒng)層面上和 Redis 主進(jìn)程競爭資源(CPU，RAM 等)。

AOF

增量的備份方式有點像 MySQL 的 binlog 機(jī)制。它把會改變數(shù)據(jù)的命令都追加寫入到備份文件里。這種方式是 Redis 服務(wù)的行為，不對外提供命令。

兩種方式優(yōu)缺點對比：

• RDB 文件較小，自定義格式有優(yōu)勢。
• AOF 文件較大，雖然 Redis 會合并掉一些指令，但是流水賬還是會很大。
• RDB 備份時間長，無法做到細(xì)粒度的備份。
• AOF 每條指令都備份，可以做到細(xì)粒度。
• 二者可以結(jié)合使用。

Amazon ElastiCache for Redis

我們使用的是 AWS 的托管服務(wù)，他們是怎么做備份的呢?

詳情可以參考官方文檔：

https://docs.aws.amazon.com/zh_cn/AmazonElastiCache/latest/red-ug/backups.html#backups-performance

Redis 2.8.22 以前：使用 BGSAVE 命令，如果預(yù)留內(nèi)存不足，可能會導(dǎo)致備份失敗。

Redis 2.8.22 及以后：如果內(nèi)存不足，使用 SAVE 命令。如果內(nèi)存充足，使用 BGSAVE 命令。

大概要預(yù)留多少內(nèi)存呢?AWS 官方推薦 25% 的內(nèi)存。很顯然我們的實例的預(yù)留內(nèi)存是不夠這個數(shù)的，所以導(dǎo)致了問題的出現(xiàn)。我覺得 AWS 可以把備份做的更好。

【51CTO原創(chuàng)稿件，合作站點轉(zhuǎn)載請注明原文作者和出處為51CTO.com】