redis系列-14點的靈異事件

概述

項目組每天14點都會遭遇驚魂時刻。一條條告警短信把工程師從午后小憩中拉回現實。之后問題又神秘消失。是PM喊你上工了？還是服務器給你開玩笑？下面請看工程師如何一步一步揪出真凶，解決問題。

如果不想看故事，可以直接跳到最后事后煙章節下看和Redis相關部分。

起因

某天下午，后端組的監控系統發出告警，服務器響應時間變長，超過了閾值。過一會兒系統自動恢復了，告警解除。

第二天差不多的時間點，監控系統又發出了同樣的告警，過幾分鍾后又恢復了。

我們決定排查這個問題。

背景

首先要介紹一下應用的架構，很簡單的三層架構的web服務。

從外到內大概是這樣的

• Load Balance:對外提供訪問入口，對內實現負載均衡。
• Nginx:放在LB后面，實現流控等功能。
• App Service :邏輯服務，多機多進程。
• Storage:MySQL和Redis組成的存儲層。

我們的服務部署在aws雲上，架構里用到了很多aws的服務。
比如ELB,EC2,RDS等

表象

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

我們收集到的信息大概是這樣的

在每天14點的時候

• QPS突增
• P99指標升高
• App服務器集群CPU、內存都升高，tcp連接數暴漲，入網流量降低
• MySQL Write IOPS升高，寫入延時升高，數據庫連接數升高

幾分鍾后，這些指標都回歸到正常水平。

排查

首先從代碼入手，看看是不是有這個時間點的定時任務。結果發現並沒有。

然后就是第一個懷疑對象MySQL

使用mysqlbinlog命令統計一下各個時間點的binlog數量

日志條數	UTC時間
624	6:00:37
396	6:00:38
933	6:00:51
834	6:00:52
402	6:01:24
2019	6:01:25
6030	6:01:26
7362	6:01:27
1479	6:01:28
1026	6:01:29
1320	6:01:30
954	6:01:31

我們又在第二天的這個時間點觀察了一下現場

使用show processlist命令抓取一下當時MySQL連接的狀態，結果發現來自App服務器的連接竟然都sleep了20秒左右，什么事兒都沒做。

初步推論

根據以上的數據可以還原一下當時的場景

• App服務器socket數激增
• App服務器不再進行邏輯處理（這個待確認）
• App服務器不再進行任何數據庫操作
• App服務器恢復讀寫數據庫
• 積壓了大量的網絡請求 讓游戲服務器cpu增加
• 大批量的寫請求涌向數據庫 造成數據庫各項指標升高

那么問題來了

• 激增的socket來自哪里？
• 或者去連接了誰？
• App服務器為什么會長達20秒沒有什么數據庫操作？
• App服務器是真的hang住了？

帶着疑問開始進一步排查

深入排查

先解決第一個問題 多出來的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掛起，導致數據庫不可寫。 而默認的備份時間窗口是這樣的。

區域	時間窗口
美國西部（俄勒岡）區域	06:00–14:00 UTC
美國西部（加利福利亞北部）區域	06:00–14:00 UTC

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

下一步就是要確認這個問題。

是在偷偷的幫我們做備份，還是實例所在的物理機上的其他實例干擾了我們？

在某個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的影響不明顯。

結論

問題出現的大致過程是這樣的

• redis2在北京時間的14點左右進行了從庫備份。
• 備份期間導致了整個reids從庫的讀取操作被阻塞住。
• 進一步導致了用戶的api請求被阻塞住。
• 這期間沒有進行任何數據庫的操作。
• 被逐漸積累的api請求，在備份完成的一小段時間內，給Nginx，App Service，Redis，RDS都帶來了不小的沖擊
• 所以出現了前文中描述的現象。

事后煙

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

Redis的持久化可以分為兩種方案；一種是全量方式RDB，一種是增量方式AOF。

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

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的托管服務，他們是怎么做備份的呢？

詳情可以參考官方文檔

Redis 2.8.22以前

使用BGSAVE命令，如果預留內存不足，可能會導致備份失敗。

Redis 2.8.22及以后

如果內存不足，使用SAVE命令。

如果內存充足，使用BGSAVE命令。

大概要預留多少內存呢？aws官方推薦25%的內存。

很顯然我們的實例的預留內存是不夠這個數的，所以導致了問題的出現。

我覺得aws可以把備份做的更好。

---

更多redis系列