装mysql最后一步没响应_每天14点遭遇惊魂时刻，如何一步一步揪出真凶？
筆者所在的公司有一款大 DAU(日活)的休閑游戲。這款游戲的后端架構(gòu)很簡(jiǎn)單，可以簡(jiǎn)單理解為通訊-邏輯-存儲(chǔ)三層結(jié)構(gòu)。其中存儲(chǔ)層大量使用了 Redis 和 MySQL。
圖片來自 Pexels
隨著存量用戶的增加，Redis 就隔三差五的出現(xiàn)問題。所以筆者打算把遇到的一系列問題以及在項(xiàng)目里的實(shí)踐都整理記錄下來。
項(xiàng)目組每天 14 點(diǎn)都會(huì)遭遇驚魂時(shí)刻。一條條告警短信把工程師從午后小憩中拉回現(xiàn)實(shí)，之后問題又神秘消失。
是 PM 喊你上工了？還是服務(wù)器給你開玩笑？下面請(qǐng)看工程師如何一步一步揪出真兇，解決問題。
1
起因
某天下午，后端組的監(jiān)控系統(tǒng)發(fā)出告警，服務(wù)器響應(yīng)時(shí)間變長(zhǎng)，超過了閾值。過一會(huì)兒系統(tǒng)自動(dòng)恢復(fù)了，告警解除。
第二天差不多的時(shí)間點(diǎn)，監(jiān)控系統(tǒng)又發(fā)出了同樣的告警，過幾分鐘后又恢復(fù)了。于是我們決定排查這個(gè)問題。
2
背景
首先要介紹一下應(yīng)用的架構(gòu)，是很簡(jiǎn)單的三層架構(gòu)的 Web 服務(wù)，從外到內(nèi)大概是這樣的：
Load Balance：對(duì)外提供訪問入口，對(duì)內(nèi)實(shí)現(xiàn)負(fù)載均衡。
Nginx：放在 LB 后面，實(shí)現(xiàn)流控等功能。
App Service：邏輯服務(wù)，多機(jī)多進(jìn)程。
Storage：MySQL 和 Redis 組成的存儲(chǔ)層。
3
表象
排查問題的第一步就是要收集信息。從監(jiān)控和日志系統(tǒng)里提取大量的相關(guān)信息，然后再分析、解決問題。我們收集到的信息大概是這樣的，在每天 14 點(diǎn)的時(shí)候：QPS 突增。
P99 指標(biāo)升高。
App 服務(wù)器集群 CPU、內(nèi)存都升高，TCP 連接數(shù)暴漲，入網(wǎng)流量降低。
MySQL Write IOPS 升高，寫入延時(shí)升高，數(shù)據(jù)庫(kù)連接數(shù)升高。
4
排查
首先從代碼入手，看看是不是有這個(gè)時(shí)間點(diǎn)的定時(shí)任務(wù)。結(jié)果發(fā)現(xiàn)并沒有。然后就是第一個(gè)懷疑對(duì)象 MySQL。使用 mysqlbinlog 命令統(tǒng)計(jì)一下各個(gè)時(shí)間點(diǎn)的 binlog 數(shù)量：
我們又在第二天的這個(gè)時(shí)間點(diǎn)觀察了一下現(xiàn)場(chǎng)，使用 show processlist 命令抓取一下當(dāng)時(shí) MySQL 連接的狀態(tài)，結(jié)果發(fā)現(xiàn)來自 App 服務(wù)器的連接竟然都 sleep 了 20 秒左右，什么事兒都沒做。初步推論
根據(jù)以上的數(shù)據(jù)可以還原一下當(dāng)時(shí)的場(chǎng)景：App 服務(wù)器 Socket 數(shù)激增。
App 服務(wù)器不再進(jìn)行邏輯處理(這個(gè)待確認(rèn))。
App 服務(wù)器不再進(jìn)行任何數(shù)據(jù)庫(kù)操作。
App 服務(wù)器恢復(fù)讀寫數(shù)據(jù)庫(kù)。
積壓了大量的網(wǎng)絡(luò)請(qǐng)求讓游戲服務(wù)器 CPU 增加。
大批量的寫請(qǐng)求涌向數(shù)據(jù)庫(kù)造成數(shù)據(jù)庫(kù)各項(xiàng)指標(biāo)升高。
激增的 Socket 來自哪里？
或者去連接了誰？
App 服務(wù)器為什么會(huì)長(zhǎng)達(dá) 20 秒沒有什么數(shù)據(jù)庫(kù)操作？
App 服務(wù)器是真的 hang 住了？
5
深入排查
先解決第一個(gè)問題：多出來的 Socket 來自哪里？App Service
在 14 點(diǎn)前，選一臺(tái) App 服務(wù)器，抓取它的 TCP 連接：
#!/bin/bashwhile?[?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
對(duì)大小差異比較大的文件進(jìn)行比對(duì)，發(fā)現(xiàn)多出來的連接來自 Nginx。Nginx 只是個(gè)代理，那就排查它的上游 Load Balance。
Load Balance
Load Balance 我們使用的是 AWS 的經(jīng)典產(chǎn)品 ELB。ELB 的日志很大，主要是分析一下這段時(shí)間內(nèi)有沒有異常的流量。經(jīng)過對(duì)比分析 13:55-14:00 和 14:00-14:05 這兩個(gè)時(shí)間段的請(qǐng)求上沒有明顯的差異。基本上都是由以下請(qǐng)求構(gòu)成：https://xxxxxxx.xxxx.xxx:443/time
https://xxxxx.xxxx.xxx:443/gateway/v1
App Service 還在正常提供服務(wù)，否則 time 請(qǐng)求不會(huì)正常返回。
App Service 所有寫數(shù)據(jù)庫(kù)的操作都處于等待的狀態(tài)。
Nginx 到 App Service 的連接得不到及時(shí)處理，所以連接很長(zhǎng)時(shí)間沒有斷開，導(dǎo)致了 Nginx 和 App Service 的 Socket 連接快速增長(zhǎng)。
MySQL
問題又回到了數(shù)據(jù)庫(kù)上，首先想到的就是備份，但是我們的備份時(shí)間不在出問題的時(shí)間段。我們使用的是 AWS 的 RDS 服務(wù)，查閱了一下 RDS 關(guān)于備份的文檔。只有在數(shù)據(jù)庫(kù)備份的時(shí)候才可能會(huì)出現(xiàn)寫 I/O 掛起，導(dǎo)致數(shù)據(jù)庫(kù)不可寫。而默認(rèn)的備份時(shí)間窗口是這樣的：
這個(gè)開始的時(shí)間也剛好在我們出問題的時(shí)間，簡(jiǎn)直是太巧合了。下一步就是要確認(rèn)這個(gè)問題。是在偷偷的幫我們做備份，還是實(shí)例所在的物理機(jī)上的其他實(shí)例干擾了我們？在某個(gè) MySQL 實(shí)例上建個(gè)新的數(shù)據(jù)庫(kù) 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í)間，這樣就能看出來在哪個(gè)時(shí)間段數(shù)據(jù)庫(kù)不可寫了。同時(shí)每秒鐘讀取這張表的最大值，記錄下結(jié)果和當(dāng)前時(shí)間，這樣就能看出來哪個(gè)時(shí)間段數(shù)據(jù)庫(kù)不可讀。
測(cè)試的腳本如下：
#!/bin/bashhost=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
這個(gè)腳本同時(shí)還每秒鐘掃描一次 MySQL 各個(gè)客戶端的工作狀態(tài)。最后得到的結(jié)論是，出現(xiàn)問題的時(shí)間點(diǎn)，數(shù)據(jù)庫(kù)可讀也可寫。問題好像陷入了困境。懷疑的點(diǎn)被一一證明沒有問題。線索也斷了。只能再回到起點(diǎn)了，繼續(xù)從代碼下手，看看哪里會(huì)造成單點(diǎn)，哪里出現(xiàn)了問題會(huì)讓所有的游戲服務(wù)器集體卡住，或者是讓數(shù)據(jù)庫(kù)操作卡住。
Redis
終于排查到了罪魁禍?zhǔn)字鹘?#xff0c;最可疑的有兩個(gè)點(diǎn)：數(shù)據(jù)庫(kù)分片的方案依賴 Redis。Redis 里存儲(chǔ)了每個(gè)用戶的數(shù)據(jù)庫(kù)分片 id，用來查找其數(shù)據(jù)所在的位置。
用戶的設(shè)備和邏輯 id 的映射關(guān)系，也存儲(chǔ)在 Redis 里。幾乎每個(gè) API 請(qǐng)求都要查找這個(gè)映射關(guān)系。
進(jìn)一步確認(rèn)嫌疑：把兩個(gè) Redis 的備份時(shí)間做出更改。Redis1 更換為 3:00-4:00utc，Redis2 更換為 7:00-8:00utc。
北京時(shí)間 11:00 左右 Redis1 正常備份，問題沒有復(fù)現(xiàn)；北京時(shí)間 14:00 左右問題沒有復(fù)現(xiàn)；北京時(shí)間 15:00 左右 Redis2 正常備份，問題復(fù)現(xiàn)。事后查看了一下 Redis1 和 Redis2 的數(shù)據(jù)量，Redis2 是 Redis1 的 5 倍左右。Redis1 占用內(nèi)存 1.3G 左右，Redis2 占用內(nèi)存 6.0G 左右。Redis1 的備份過程幾乎在瞬間完成，對(duì) App 的影響不明顯。6
結(jié)論
問題出現(xiàn)的大致過程是這樣的：Redis2 在北京時(shí)間的 14 點(diǎn)左右進(jìn)行了從庫(kù)備份。
備份期間導(dǎo)致了整個(gè) Reids 從庫(kù)的讀取操作被阻塞住。
進(jìn)一步導(dǎo)致了用戶的 API 請(qǐng)求被阻塞住。
這期間沒有進(jìn)行任何數(shù)據(jù)庫(kù)的操作。
被逐漸積累的 API 請(qǐng)求，在備份完成的一小段時(shí)間內(nèi)，給 Nginx，App Service，Redis，RDS 都帶來了不小的沖擊。
所以出現(xiàn)了前文中描述的現(xiàn)象。
7
事后煙
其實(shí)問題的根源還在 Redis 的備份上，我們就來聊一下 Redis 的備份。Redis 的持久化可以分為兩種方案：全量方式 RDB
增量方式 AOF
詳情可以參考官方中文翻譯：
http://www.redis.cn/topics/persistence.htmlRDB
把內(nèi)存中的全部數(shù)據(jù)按格式寫入備份文件，這就是全量備份。它又分為兩種不同的形式。涉及到的 Redis 命令是 SAVE/BGSAVE：SAVE：眾所周知，Redis 服務(wù)都是單線程的。SAVE 和其他常見的命令一樣，也是運(yùn)行在主進(jìn)程里的。可想而知，如果 SAVE 的動(dòng)作很慢，其他命令都得排隊(duì)等著它結(jié)束。
BGSAVE：BGSAVE 命令也可以觸發(fā)全量備份，但是 Redis 會(huì)為它 Fork 出來一個(gè)子進(jìn)程，BGSAVE 命令運(yùn)行在子進(jìn)程里，它不會(huì)影響到 Redis 的主進(jìn)程執(zhí)行其他指令。
它唯一的影響可能就是會(huì)在操作系統(tǒng)層面上和 Redis 主進(jìn)程競(jìng)爭(zhēng)資源(CPU，RAM 等)。
AOF
增量的備份方式有點(diǎn)像 MySQL 的 binlog 機(jī)制。它把會(huì)改變數(shù)據(jù)的命令都追加寫入到備份文件里。這種方式是 Redis 服務(wù)的行為，不對(duì)外提供命令。兩種方式優(yōu)缺點(diǎn)對(duì)比：RDB 文件較小，自定義格式有優(yōu)勢(shì)。
AOF 文件較大，雖然 Redis 會(huì)合并掉一些指令，但是流水賬還是會(huì)很大。
RDB 備份時(shí)間長(zhǎng)，無法做到細(xì)粒度的備份。
AOF 每條指令都備份，可以做到細(xì)粒度。
二者可以結(jié)合使用。
Amazon ElastiCache for Redis
我們使用的是 AWS 的托管服務(wù)，他們是怎么做備份的呢？詳情可以參考官方文檔：
https://docs.aws.amazon.com/zh_cn/AmazonElastiCache/latest/red-ug/backups.html#backups-performanceRedis 2.8.22 以前：使用 BGSAVE 命令，如果預(yù)留內(nèi)存不足，可能會(huì)導(dǎo)致備份失敗。
Redis 2.8.22 及以后：如果內(nèi)存不足，使用 SAVE 命令。如果內(nèi)存充足，使用 BGSAVE 命令。
大概要預(yù)留多少內(nèi)存呢？AWS 官方推薦 25% 的內(nèi)存。很顯然我們的實(shí)例的預(yù)留內(nèi)存是不夠這個(gè)數(shù)的，所以導(dǎo)致了問題的出現(xiàn)。我覺得 AWS 可以把備份做的更好。
作者：三石君
編輯：陶家龍、孫淑娟
來源：http://www.cnblogs.com/zhroot/
征稿：有投稿、尋求報(bào)道意向技術(shù)人請(qǐng)聯(lián)絡(luò) editor@51cto.com
精彩文章推薦：
炸了！技術(shù)總監(jiān)“刪庫(kù)跑路”被判刑兩年多Netty、Kafka中的零拷貝技術(shù)到底有多牛?從華為到阿里，我的15年職場(chǎng)歷程總結(jié)
以上是生活随笔為你收集整理的装mysql最后一步没响应_每天14点遭遇惊魂时刻，如何一步一步揪出真凶？的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： ora-07445 oracle 9,O
- 下一篇： java double add,Java