每天14點遭遇驚魂時刻，如何一步一步揪出真兇？
原創【51CTO.com原創稿件】筆者所在的公司有一款大 DAU(日活)的休閑游戲。這款游戲的后端架構很簡單，可以簡單理解為通訊-邏輯-存儲三層結構。其中存儲層大量使用了 Redis 和 MySQL。
圖片來自 Pexels
隨著存量用戶的增加，Redis 就隔三差五的出現問題。所以筆者打算把遇到的一系列問題以及在項目里的實踐都整理記錄下來。
項目組每天 14 點都會遭遇驚魂時刻。一條條告警短信把工程師從午后小憩中拉回現實，之后問題又神秘消失。
是 PM 喊你上工了?還是服務器給你開玩笑?下面請看工程師如何一步一步揪出真兇，解決問題。
1、起因
某天下午，后端組的監控系統發出告警，服務器響應時間變長，超過了閾值。過一會兒系統自動恢復了，告警解除。
第二天差不多的時間點，監控系統又發出了同樣的告警，過幾分鐘后又恢復了。于是我們決定排查這個問題。
2、背景
首先要介紹一下應用的架構，是很簡單的三層架構的 Web 服務，從外到內大概是這樣的：
- Load Balance：對外提供訪問入口，對內實現負載均衡。
- Nginx：放在 LB 后面，實現流控等功能。
- App Service：邏輯服務，多機多進程。
- Storage：MySQL 和 Redis 組成的存儲層。
我們的服務部署在 AWS 云上，架構里用到了很多 AWS 的服務，比如 ELB，EC2，RDS 等。
3、表象
排查問題的第一步就是要收集信息。從監控和日志系統里提取大量的相關信息，然后再分析、解決問題。
我們收集到的信息大概是這樣的，在每天 14 點的時候：
- QPS 突增。
- P99 指標升高。
- App 服務器集群 CPU、內存都升高，TCP 連接數暴漲，入網流量降低。
- MySQL Write IOPS 升高，寫入延時升高，數據庫連接數升高。
幾分鐘后，這些指標都回歸到正常水平。
4、排查
首先從代碼入手，看看是不是有這個時間點的定時任務。結果發現并沒有。然后就是第一個懷疑對象 MySQL。
使用 mysqlbinlog 命令統計一下各個時間點的 binlog 數量：
我們又在第二天的這個時間點觀察了一下現場，使用 show processlist 命令抓取一下當時 MySQL 連接的狀態，結果發現來自 App 服務器的連接竟然都 sleep 了 20 秒左右，什么事兒都沒做。
初步推論
根據以上的數據可以還原一下當時的場景：
- App 服務器 Socket 數激增。
- App 服務器不再進行邏輯處理(這個待確認)。
- App 服務器不再進行任何數據庫操作。
- App 服務器恢復讀寫數據庫。
- 積壓了大量的網絡請求讓游戲服務器 CPU 增加。
- 大批量的寫請求涌向數據庫造成數據庫各項指標升高。
那么問題來了：
- 激增的 Socket 來自哪里?
- 或者去連接了誰?
- App 服務器為什么會長達 20 秒沒有什么數據庫操作?
- App 服務器是真的 hang 住了?
帶著疑問開始進一步排查。
5、深入排查
先解決第一個問題：多出來的 Socket 來自哪里?
App Service
在 14 點前，選一臺 App 服務器，抓取它的 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
對大小差異比較大的文件進行比對，發現多出來的連接來自 Nginx。Nginx 只是個代理，那就排查它的上游 Load Balance。
Load Balance
Load Balance 我們使用的是 AWS 的經典產品 ELB。ELB 的日志很大，主要是分析一下這段時間內有沒有異常的流量。
經過對比分析 13:55-14:00 和 14:00-14:05 這兩個時間段的請求上沒有明顯的差異。
基本上都是由以下請求構成：
- https://xxxxxxx.xxxx.xxx:443/time
- https://xxxxx.xxxx.xxx:443/gateway/v1
但是從 14:00:53 開始，帶 gateway 的請求大部分都返回 504，帶 time 的請求都正常返回。504 表示網關超時，就是 App 響應超時了。
根據這個信息又可以推斷出一些情況：
- App Service 還在正常提供服務，否則 time 請求不會正常返回。
- App Service 所有寫數據庫的操作都處于等待的狀態。
- Nginx 到 App Service 的連接得不到及時處理，所以連接很長時間沒有斷開，導致了 Nginx 和 App Service 的 Socket 連接快速增長。
根據以上，基本上可以排除是 ELB，Nginx 帶來的問題。那么問題就剩下一個，什么數據庫長時間不可寫呢? 而且每天都在固定時間。
MySQL
問題又回到了數據庫上，首先想到的就是備份，但是我們的備份時間不在出問題的時間段。
我們使用的是 AWS 的 RDS 服務，查閱了一下 RDS 關于備份的文檔。只有在數據庫備份的時候才可能會出現寫 I/O 掛起，導致數據庫不可寫。
而默認的備份時間窗口是這樣的：
這個開始的時間也剛好在我們出問題的時間，簡直是太巧合了。
下一步就是要確認這個問題。是在偷偷的幫我們做備份，還是實例所在的物理機上的其他實例干擾了我們?
在某個 MySQL 實例上建個新的數據庫 test，創建一張新表 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;
每秒鐘往這張表里寫條數據，數據的內容是當前時間，這樣就能看出來在哪個時間段數據庫不可寫了。
同時每秒鐘讀取這張表的最大值，記錄下結果和當前時間，這樣就能看出來哪個時間段數據庫不可讀。
測試的腳本如下：
- #!/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 各個客戶端的工作狀態。最后得到的結論是，出現問題的時間點，數據庫可讀也可寫。
問題好像陷入了困境。懷疑的點被一一證明沒有問題。線索也斷了。只能再回到起點了，繼續從代碼下手，看看哪里會造成單點，哪里出現了問題會讓所有的游戲服務器集體卡住，或者是讓數據庫操作卡住。
Redis
終于排查到了罪魁禍首主角，最可疑的有兩個點：
- 數據庫分片的方案依賴 Redis。Redis 里存儲了每個用戶的數據庫分片 id，用來查找其數據所在的位置。
- 用戶的設備和邏輯 id 的映射關系，也存儲在 Redis 里。幾乎每個 API 請求都要查找這個映射關系。
以上兩點幾乎是一個 API 請求的開始，如果這兩點出現了問題，后續的操作都會被卡住。
經過和 OPS 確認，這兩個 Redis 的備份時間窗口確實在 6:00-7:00utc。而且備份都是在從庫上進行的，我們程序里的讀操作也是在從庫上進行的。
通過 Redis 的 info 命令，參考 Redis 最近一次的備份時間，時間點也剛好都在北京時間 14:01 左右。
進一步確認嫌疑：把兩個 Redis 的備份時間做出更改。Redis1 更換為 3:00-4:00utc，Redis2 更換為 7:00-8:00utc。
北京時間 11:00 左右 Redis1 正常備份，問題沒有復現;北京時間 14:00 左右問題沒有復現;北京時間 15:00 左右 Redis2 正常備份，問題復現。
事后查看了一下 Redis1 和 Redis2 的數據量，Redis2 是 Redis1 的 5 倍左右。
Redis1 占用內存 1.3G 左右，Redis2 占用內存 6.0G 左右。Redis1 的備份過程幾乎在瞬間完成，對 App 的影響不明顯。
6、結論
問題出現的大致過程是這樣的：
- Redis2 在北京時間的 14 點左右進行了從庫備份。
- 備份期間導致了整個 Reids 從庫的讀取操作被阻塞住。
- 進一步導致了用戶的 API 請求被阻塞住。
- 這期間沒有進行任何數據庫的操作。
- 被逐漸積累的 API 請求，在備份完成的一小段時間內，給 Nginx，App Service，Redis，RDS 都帶來了不小的沖擊。
- 所以出現了前文中描述的現象。
7、事后煙
其實問題的根源還在 Redis 的備份上，我們就來聊一下 Redis 的備份。
Redis 的持久化可以分為兩種方案：
- 全量方式 RDB
- 增量方式 AOF
詳情可以參考官方中文翻譯：
http://www.redis.cn/topics/persistence.html
RDB
把內存中的全部數據按格式寫入備份文件，這就是全量備份。它又分為兩種不同的形式。
涉及到的 Redis 命令是 SAVE/BGSAVE：
- SAVE：眾所周知，Redis 服務都是單線程的。SAVE 和其他常見的命令一樣，也是運行在主進程里的。可想而知，如果 SAVE 的動作很慢，其他命令都得排隊等著它結束。
- BGSAVE：BGSAVE 命令也可以觸發全量備份，但是 Redis 會為它 Fork 出來一個子進程，BGSAVE 命令運行在子進程里，它不會影響到 Redis 的主進程執行其他指令。它唯一的影響可能就是會在操作系統層面上和 Redis 主進程競爭資源(CPU，RAM 等)。
AOF
增量的備份方式有點像 MySQL 的 binlog 機制。它把會改變數據的命令都追加寫入到備份文件里。這種方式是 Redis 服務的行為，不對外提供命令。
兩種方式優缺點對比：
- RDB 文件較小，自定義格式有優勢。
- AOF 文件較大，雖然 Redis 會合并掉一些指令，但是流水賬還是會很大。
- RDB 備份時間長，無法做到細粒度的備份。
- AOF 每條指令都備份，可以做到細粒度。
- 二者可以結合使用。
Amazon ElastiCache for Redis
我們使用的是 AWS 的托管服務，他們是怎么做備份的呢?
詳情可以參考官方文檔：
https://docs.aws.amazon.com/zh_cn/AmazonElastiCache/latest/red-ug/backups.html#backups-performance
Redis 2.8.22 以前：使用 BGSAVE 命令，如果預留內存不足，可能會導致備份失敗。
Redis 2.8.22 及以后：如果內存不足，使用 SAVE 命令。如果內存充足，使用 BGSAVE 命令。
大概要預留多少內存呢?AWS 官方推薦 25% 的內存。很顯然我們的實例的預留內存是不夠這個數的，所以導致了問題的出現。我覺得 AWS 可以把備份做的更好。
【51CTO原創稿件，合作站點轉載請注明原文作者和出處為51CTO.com】
