數(shù)據(jù)庫故障引發(fā)的“血案”
標(biāo)題聽起來很聳人聽聞,不過確實(shí)沒有夸大的意思,對(duì)于我們來說確實(shí)算得上”血案“了。這個(gè)問題最終導(dǎo)致了某個(gè)底層的核心應(yīng)用15分鐘內(nèi)不可用,間接導(dǎo)致上層很多應(yīng)用也出現(xiàn)了問題,尤其是一些支付相關(guān)的業(yè)務(wù)也出現(xiàn)了不可用情況。由于故障影響較大,該故障在內(nèi)部定級(jí)很高。故障排查過程也算是一波三折,中間的槽點(diǎn)也比較多,特別是對(duì)網(wǎng)絡(luò)比較了解的大佬能一眼看出來問題。這個(gè)故障的排查工作我也深度參與了,這里做一下總結(jié),希望能給大家一些參考。
0. 文章導(dǎo)讀
本文約 7000 字,配圖 26 張。文章相對(duì)比較長(zhǎng),因此這里對(duì)文章結(jié)構(gòu)做些介紹。本篇文章分為5個(gè)章節(jié),各章節(jié)內(nèi)容概括如下:
- 故障現(xiàn)象:本章對(duì)故障現(xiàn)象進(jìn)行了介紹,在閱讀后續(xù)內(nèi)容前,需先搞清楚故障現(xiàn)象
- 故障排查過程:本章介紹了故障排查過程,并給出了初步結(jié)論。
- 故障復(fù)現(xiàn):本章基于故障排查結(jié)論,針對(duì)性的進(jìn)行了故障復(fù)現(xiàn)和驗(yàn)證,并給出了故障的處理措施
- 再次探索:重新對(duì)故障排查過程進(jìn)行審視,并針對(duì)其中疑點(diǎn)再次進(jìn)行探索,嘗試尋找”真相“
- 總結(jié):本章對(duì)故障和排查過程中存在的一些問題進(jìn)行了回顧與總結(jié)
需要說明的是,為了降低圖片大小,一些異常棧信息被刪除了,但核心調(diào)用都在。
1. 故障現(xiàn)象
4月的某個(gè)周日下午2點(diǎn)前后,一個(gè)核心應(yīng)用出現(xiàn)大量的報(bào)警,但是一小會(huì)后又自動(dòng)恢復(fù)了,從監(jiān)控上看故障持續(xù)時(shí)間約為15分鐘。翻看了業(yè)務(wù)日志,發(fā)現(xiàn)里面有很多 druid 相關(guān)的報(bào)錯(cuò),看起來像是 druid 出問題了。

圖1:業(yè)務(wù)線程大量拋出獲取連接超時(shí)異常

圖2:druid 連接生產(chǎn)者線程拋出網(wǎng)絡(luò)異常
后來從 DBA 那邊得知,阿里云 RDS 由于物理機(jī)發(fā)生故障,在13:57 進(jìn)行了自動(dòng)主備切換。由于 RDS 主備切換時(shí)間與我們的應(yīng)用發(fā)生故障的時(shí)間很接近,因此初步判斷該故障和阿里云 RDS 切換有關(guān)。從現(xiàn)象上看,阿里云 RDS 執(zhí)行主備切換后,我們的應(yīng)用似乎沒有切換成功,仍然連接到了故障機(jī)上。由于 DBA 之前也做過很多次主備切換演練,一直都沒發(fā)生過什么事情,所以這個(gè)問題在當(dāng)時(shí)看起來還是挺費(fèi)解的。
以上就是故障的背景和現(xiàn)象,下面開始分析故障原因。
2. 故障排查過程
在展開分析前,先給大家介紹一下 druid 的并發(fā)模型,做一些技術(shù)鋪墊。
2.1 背景知識(shí)介紹
druid 數(shù)據(jù)源使用生產(chǎn)者消費(fèi)者模型維護(hù)連接池,當(dāng)連接池中沒有連接時(shí),消費(fèi)者線程會(huì)通知生產(chǎn)者線程創(chuàng)建連接。生產(chǎn)者創(chuàng)建好連接后,會(huì)將連接放到池中,并通知消費(fèi)者線程取連接。如果消費(fèi)者線程在設(shè)定時(shí)間沒沒取到連接,會(huì)拋出一個(gè)超時(shí)異常。

圖3:druid 并發(fā)模型
注意,生產(chǎn)者線程是單線程,如果這個(gè)線程在某些情況下阻塞住,會(huì)造成大量的消費(fèi)者線程無法獲取到連接。
2.2 排查過程
2.2.1 初步排查
這個(gè)問題最早是我接手排查的,當(dāng)時(shí)很多信息都還沒有,只有異常日志。剛開始排查的時(shí)候,我翻看了其中一臺(tái)機(jī)器上的日志,發(fā)現(xiàn)日志中只有大量的 GetConnectionTimeoutException 異常,沒有 druid 生產(chǎn)者線程拋出的異常。

圖4:消費(fèi)者線程拋出異常
在消費(fèi)者線程拋出的異常信息里,包含了兩個(gè)與生產(chǎn)者有關(guān)的數(shù)據(jù),通過這兩個(gè)數(shù)據(jù)可以了解到生產(chǎn)者處于的狀態(tài)。第一個(gè)是 creating,表示生產(chǎn)者當(dāng)前正在創(chuàng)建連接。第二個(gè)是 createElapseMillis,表示消費(fèi)者超時(shí)返回時(shí),生產(chǎn)者創(chuàng)建連接所消耗的時(shí)間。上圖中,createElapseMillis 值約為900秒,這明顯是有問題的,說明生產(chǎn)者線程應(yīng)該是被阻塞住了。因此根據(jù)這個(gè)信息,我給出了一個(gè)初步結(jié)論:
生產(chǎn)者線程被卡住,很可能的原因是在創(chuàng)建連接時(shí)沒有配置超時(shí)時(shí)間,可以通過在數(shù)據(jù)庫 URL 后面追加一個(gè) connectTimeout 參數(shù)解決這個(gè)問題。
排查到這里好像也能解釋通,但是這里有很多疑問沒有解決:到底是在哪個(gè)方法上卡住了?配置這個(gè)參數(shù)是否真的有用,能否復(fù)現(xiàn)驗(yàn)證?不回答掉這些問題,這個(gè)故障排查結(jié)論顯然不能說服人。因此后續(xù)有更多人參與進(jìn)來排查,收集到的信息也越來越多。
2.2.2 深入排查
這個(gè)時(shí)候,我們的 DBA 開始找阿里云技術(shù)支持溝通,得到的答復(fù) RDS 物理機(jī)出現(xiàn)了故障,觸發(fā)了自動(dòng)主備切換機(jī)制。另一方面,其他同事詳細(xì)閱讀了更多機(jī)器的錯(cuò)誤日志,發(fā)現(xiàn)了生產(chǎn)者線程也拋出了異常。

圖5:druid 生產(chǎn)線線程拋出網(wǎng)絡(luò)異常
奇怪的是,其中有兩臺(tái)機(jī)器的日志里找不到生產(chǎn)者的異常。后來詢問了應(yīng)用負(fù)責(zé)人,才了解到他在 14:10 重啟過應(yīng)用,剩余機(jī)器還沒來得及重啟,服務(wù)就已經(jīng)恢復(fù)了。不巧的是,我剛開始排查的時(shí)候,查看的日志正是被重啟過的機(jī)器的日志。這里也凸顯排查問題時(shí),廣泛收集信息的重要性。除了生產(chǎn)者線程拋出了這個(gè)異常,部分消費(fèi)者線程也拋出了同樣的異常:

圖6:消費(fèi)者線程拋出網(wǎng)絡(luò)異常
如上,生產(chǎn)者和部分消費(fèi)者線程都是在卡住900多秒后拋出異常,通過查閱 TCP 相關(guān)的資料,一起排查的同事認(rèn)為這個(gè)時(shí)間應(yīng)該是底層網(wǎng)絡(luò)最大的超時(shí)時(shí)間導(dǎo)致的。因此推斷 MySQL 物理機(jī)發(fā)生故障后,不再響應(yīng)客戶端的任何數(shù)據(jù)包。客戶端機(jī)器底層網(wǎng)絡(luò)在經(jīng)過多次重試后失敗后,自己關(guān)閉了連接,上層應(yīng)用拋出 SocketException。通過資料,我們了解到 net.ipv4.tcp_retries2 內(nèi)核參數(shù)用于控制 TCP 的重傳。Linux 官方文檔有相關(guān)說明:
tcp_retries2 - INTEGER
This value influences the timeout of an alive TCP connection,
when RTO retransmissions remain unacknowledged.
Given a value of N, a hypothetical TCP connection following
exponential backoff with an initial RTO of TCP_RTO_MIN would
retransmit N times before killing the connection at the (N+1)th RTO.The default value of 15 yields a hypothetical timeout of 924.6
seconds and is a lower bound for the effective timeout.
TCP will effectively time out at the first RTO which exceeds the
hypothetical timeout.

圖7:Linux TCP 超時(shí)重傳情況;圖片來源:Marco Pracucci
排查到這里,很多東西都能解釋通了,似乎可以“結(jié)案”了。可是情況真的如此嗎?由于沒有當(dāng)時(shí)的抓包數(shù)據(jù),大家還是沒法確定是不是這個(gè)原因。于是接下來,我按照這個(gè)排查結(jié)論進(jìn)行了復(fù)現(xiàn)。
3. 故障復(fù)現(xiàn)
3.1 準(zhǔn)備工作
為了進(jìn)行較為準(zhǔn)確的復(fù)現(xiàn),我們?cè)谝慌_(tái)與線上配置相同的 ECS 上部署業(yè)務(wù)應(yīng)用。在內(nèi)網(wǎng)的另一臺(tái) ECS 上搭建了一個(gè) MySQL 服務(wù),并把線上數(shù)據(jù)同步到這個(gè)數(shù)據(jù)庫中。由于我們沒法制造 MySQL 物理機(jī)故障,因此我們通過 iptables 配置防火墻策略來模擬因機(jī)器故障導(dǎo)致的網(wǎng)絡(luò)層故障,比如不響應(yīng)客戶端請(qǐng)求。最后我們通過 arthas 對(duì) druid 生產(chǎn)者線程進(jìn)行監(jiān)控,觀測(cè)連接創(chuàng)建耗時(shí)情況。
3.2 背景知識(shí)介紹
在展開后續(xù)內(nèi)容前,先介紹一下 MySQL 驅(qū)動(dòng)與服務(wù)端建立連接的過程。示意圖如下:

圖8:MySQL 客戶端與服務(wù)端通信過程
這里簡(jiǎn)單講解下,業(yè)務(wù)應(yīng)用在建立一個(gè) MySQL 數(shù)據(jù)庫連接時(shí),首先要完成 TCP 三次握手,待 TCP 連接建立完畢后,再基于 TCP 連接進(jìn)行應(yīng)用層的握手。主要是互換一些信息,以及登錄認(rèn)證。服務(wù)端握手信息主要返回的是服務(wù)器的版本,服務(wù)器接受的登錄認(rèn)證方式,以及其他用于認(rèn)證的數(shù)據(jù)。客戶端收到數(shù)據(jù)庫的握手信息后,將用戶名和密碼加密后進(jìn)行登錄認(rèn)證,隨后服務(wù)端返回認(rèn)證結(jié)果。下面我們抓包看一下雙方的交互過程。
客戶端 ip: 172.***.***.141
服務(wù)端 ip: 172.***.***.251
在客戶端機(jī)器上進(jìn)行抓包,命令如下:
tcpdump -i eth0 host 172.***.***.251 -w mysql.pcap
抓包結(jié)果如下:

圖9:MySQL 連接建立過程抓包結(jié)果1

圖10:MySQL 連接建立過程抓包結(jié)果2
我們后續(xù)將使用 Version 作為服務(wù)器握手報(bào)文段的特征字符串,根據(jù)這個(gè)特征配置防火墻規(guī)則。
3.3 故障復(fù)現(xiàn)
本節(jié),我們除了要驗(yàn)證故障出現(xiàn)的可能場(chǎng)景,還要驗(yàn)證我們的解決辦法是否有效。在進(jìn)行復(fù)現(xiàn)前,我們要修改一下 druid 的配置,保證 druid 可以快速關(guān)閉空閑連接,方便驗(yàn)證連接創(chuàng)建過程。
<bean id="dataSource" class="com.alibaba.druid.pool.DruidDataSource" init-method="init" destroy-method="close">
<!-- 不配置超時(shí)時(shí)間,與線上配置保持一致 -->
<property name="url" value="jdbc:mysql://172.***.***.251:3306/***db" />
<!-- 最小空閑連接數(shù) -->
<property name="minIdle" value="0"/>
<!-- 初始連接數(shù) -->
<property name="initialSize" value="0"/>
<!-- 每隔1.5秒檢測(cè)連接是否需要被驅(qū)逐 -->
<property name="timeBetweenEvictionRunsMillis" value="1500" />
<!-- 最小驅(qū)逐時(shí)間,連接空閑時(shí)間一旦超過這個(gè)時(shí)間,就會(huì)被關(guān)閉 -->
<property name="minEvictableIdleTimeMillis" value="3000" />
</bean>
3.3.1 故障場(chǎng)景推斷
根據(jù)生產(chǎn)者線程拋出的異常顯示,生產(chǎn)者線程是在與 MySQL 服務(wù)端進(jìn)行應(yīng)用層握手時(shí)卡住的,異常日志如下:

圖11: druid 生產(chǎn)者線程拋出的異常
根據(jù)這個(gè)報(bào)錯(cuò)日志我們可以判斷出問題是出在了 TCP 連接建立后,MySQL 應(yīng)用層握手期間時(shí)。之所以可以這么肯定,是因?yàn)榇a都到了應(yīng)用層握手階段,TCP 層連接的建立肯定是完成了,否則應(yīng)該會(huì)出現(xiàn)類似無法連接的錯(cuò)誤。因此我們只需要驗(yàn)證 MySQL 客戶端與服務(wù)端進(jìn)行應(yīng)用層握手失敗的場(chǎng)景即可,不過我們可以稍微多驗(yàn)證一些其他場(chǎng)景,增加對(duì)底層網(wǎng)絡(luò)行為的了解。下面我們進(jìn)行三個(gè)場(chǎng)景的模擬:
場(chǎng)景一:服務(wù)端不響應(yīng)客戶端 SYN 報(bào)文段,TCP 無法完成三次握手
場(chǎng)景二:TCP 連接可以正常建立,但是服務(wù)端不與客戶端進(jìn)行應(yīng)用層握手
場(chǎng)景三:連接池中已經(jīng)建立好的連接無法與服務(wù)端通信,導(dǎo)致消費(fèi)者線程被阻塞
3.3.2 故障復(fù)現(xiàn)與驗(yàn)證
3.3.2.1 故障場(chǎng)景一
預(yù)期現(xiàn)象:TCP 數(shù)據(jù)包被丟棄,客戶端不停重試。druid 生產(chǎn)者線程被阻塞住,數(shù)據(jù)庫連接無法建立
步驟一:場(chǎng)景模擬
登錄到 MySQL 服務(wù)器,設(shè)置防火墻規(guī)則,丟棄所有來自客戶端的數(shù)據(jù)包
iptables -I INPUT -s 172.***.***.141 -j DROP
步驟二:觸發(fā)數(shù)據(jù)庫訪問,觀察現(xiàn)象
登錄業(yè)務(wù)機(jī)器,使用 arthas 觀察 druid 生產(chǎn)者線程執(zhí)行情況,命令如下:
trace com.alibaba.druid.pool.DruidAbstractDataSource createPhysicalConnection -n 1000 -j
觸發(fā)一個(gè)數(shù)據(jù)庫訪問,由于連接池中沒有連接,druid 會(huì)去創(chuàng)建一個(gè)連接。現(xiàn)象如下:

圖12:底層網(wǎng)絡(luò)故障,druid 新建連接耗時(shí)情況
可以看出,TCP 連接無法建立時(shí),druid 的 DruidAbstractDataSource#createPhysicalConnection 方法會(huì)消耗掉約127秒,且會(huì)拋出異常。取消掉服務(wù)端的防火墻規(guī)則:觀察正常情況下,新建連接耗時(shí)情況:
iptables -D INPUT -s 172.***.***.141 -j DROP

圖13:正常情況下,druid 新建連接耗時(shí)情況
如上,正常情況和異常情況耗時(shí)對(duì)比還是很明顯的,那這 127 秒耗時(shí)是如何來的呢?下面分析一下。
異常情況分析
TCP 在建立連接過程中,如果第一個(gè) SYN 報(bào)文段丟失(沒收到另一端的 ACK 報(bào)文),Linux 系統(tǒng)會(huì)進(jìn)行重試,重試一定次數(shù)后終止。初始的 SYN 重試次數(shù)受內(nèi)核參數(shù) tcp_syn_retries,該參數(shù)默認(rèn)值為6。內(nèi)核參數(shù)說明如下:
tcp_syn_retries - INTEGER
Number of times initial SYNs for an active TCP connection attempt
will be retransmitted. Should not be higher than 127. Default value
is 6, which corresponds to 63 seconds till the last retransmission
with the current initial RTO of 1 second. With this the final timeout
for an active TCP connection attempt will happen after 127 seconds.
注意最后一句話,與我們使用 arthas trace 命令得到的結(jié)果基本是一致的。下面再抓個(gè)包觀察一下:

圖14:TCP SYN 重傳情況
如上,第一個(gè)包是客戶端初始的握手包,后面6個(gè)包都是進(jìn)行重試。第8個(gè)包發(fā)出時(shí),時(shí)間正好過去了 127 秒,與內(nèi)核參數(shù)說明是一致的。到這里,關(guān)于 TCP 連接無法創(chuàng)建成功的問題就說清楚了。由于我們的應(yīng)用被卡住了 900 多秒,因此顯然可以排除 TCP 握手失敗的情況了。不過雖然原因不是這個(gè),但如果 druid 生產(chǎn)者線程被卡住 127 秒,那也是相當(dāng)危險(xiǎn)的。如何預(yù)防呢?
預(yù)防連接超時(shí)問題
通過配置 connectTimeout 參數(shù),可以降低 TCP SYN 重試時(shí)間,配置如下:
jdbc:mysql://172.***.***.251:3306/***db?connectTimeout=3000
再發(fā)起一個(gè)數(shù)據(jù)庫請(qǐng)求驗(yàn)證一下配置是否有效。

圖15:配置 connectTimeout 參數(shù)后,druid 生產(chǎn)者線程超時(shí)情況
如上圖,druid 生產(chǎn)者線程調(diào)用 DruidAbstractDataSource#createPhysicalConnection 消耗了 3 秒,符合預(yù)期,說明配置有效。客戶端會(huì)拋出的異常如下:

圖16:客戶端拋出的異常細(xì)節(jié)
3.3.2.2 故障場(chǎng)景二
這次我們來模擬底層網(wǎng)絡(luò)正常,但是應(yīng)用層不正常的情況,即 MySQL 服務(wù)器不與客戶端進(jìn)行握手。
預(yù)期現(xiàn)象:druid 生產(chǎn)者線程卡住約900秒后報(bào)錯(cuò)返回
步驟一:模擬場(chǎng)景
在 MySQL 服務(wù)器上配置防火墻規(guī)則,禁止 MySQL 握手?jǐn)?shù)據(jù)包流出。
# 使用 iptables 的 string 模塊進(jìn)行字符串匹配
iptables -I OUTPUT -m string --algo bm --string "5.7.34-log" -j DROP
查看防火墻規(guī)則

圖17:防火墻規(guī)則列表
步驟二:觀察現(xiàn)象
這次我們通過消費(fèi)者線程拋出的異常日志來觀察 druid 生產(chǎn)者線程的創(chuàng)建時(shí)間,異常日志如下:

圖18:消費(fèi)者線程異常日志
如上,消費(fèi)者線程的異常信息里顯示生產(chǎn)者線程以及被阻塞了 1247 秒,且這個(gè)值隨著時(shí)間的推移越來越長(zhǎng)。遠(yuǎn)遠(yuǎn)超過了 900 秒,與預(yù)期不符合,原因沒有深入探究。不過,我們似乎發(fā)現(xiàn)了比原故障更嚴(yán)重的問題,排查到這里好像可以停下腳步了。
預(yù)防 MySQL 應(yīng)用層握手超時(shí)
由于 connectTimeout 僅作用在網(wǎng)絡(luò)層,對(duì)應(yīng)用層的通信無效,所以這次我們要換個(gè)參數(shù)了。這次我們使用的參數(shù)是 socketTimeout,配置如下:
jdbc:mysql://172.***.***.251:3306/***db?connectTimeout=3000&socketTimeout=5000
設(shè)定 socketTimeout 參數(shù)值為 5000 毫秒,驗(yàn)證服務(wù)端不與客戶端握手情況下,客戶端能否在 5 秒后超時(shí)返回。arthas 監(jiān)控如下:

圖19:arthas trace 監(jiān)控
結(jié)果符合預(yù)期,druid 生產(chǎn)者線程確實(shí)在 5 秒后報(bào)錯(cuò)返回了,錯(cuò)誤信息如下:

圖20:druid 生產(chǎn)者線程超時(shí)返回情況
如上,通過配置 socketTimeout 可以保證 druid 在服務(wù)端不進(jìn)行握手的情況下超時(shí)返回。
3.3.2.3 故障場(chǎng)景三
最后一個(gè)場(chǎng)景用于復(fù)現(xiàn)在 MySQL 物理機(jī)出故障,不響應(yīng)客戶端的 SQL 請(qǐng)求。
預(yù)期現(xiàn)象:客戶端不停重試,直至 924 秒后超時(shí)返回
要模擬這種場(chǎng)景,可以在 MySQL 服務(wù)端丟棄掉來自客戶端的所有數(shù)據(jù)包,防火墻配置參考上面的內(nèi)容。直接看現(xiàn)象吧。

圖21:消費(fèi)者線程超時(shí)返回
如上,消費(fèi)者線程超時(shí)返回時(shí)間與 924 秒非常接近,基本可以判定多次重試失敗后,超時(shí)返回了。抓包佐證一下:

圖22:TCP 連接重試情況
最后一個(gè)數(shù)據(jù)包發(fā)出的時(shí)間證明了我們的判斷是對(duì)的。從上面的抓包結(jié)果可以看出,總共進(jìn)行了16次重試。前面說過,TCP 非 SYN 重試受內(nèi)核參數(shù) ipv4.tcp_retries2 影響,該參數(shù)值默認(rèn)為 15,為什么這里進(jìn)行了 16 次重試呢?這里簡(jiǎn)單說明一下吧,這里的 15 是用來計(jì)算超時(shí)總時(shí)長(zhǎng)的,并不代表重傳次數(shù),更詳細(xì)的解釋大家 STFW。
場(chǎng)景三的預(yù)防方式與場(chǎng)景二相同,都是通過配置 socketTimeout,就不贅述了。
3.4 小結(jié)
到此,整個(gè)的復(fù)現(xiàn)過程就結(jié)束了。通過對(duì)故障進(jìn)行復(fù)現(xiàn),似乎證明了我們之前的排查結(jié)果是正確的。與此同時(shí),我們也對(duì) connectTimeout 和 socketTimeout 兩個(gè)配置的有效性進(jìn)行了驗(yàn)證,結(jié)果也是符合預(yù)期的。但是復(fù)現(xiàn)過程中,生產(chǎn)者被卡住的時(shí)間遠(yuǎn)遠(yuǎn)長(zhǎng)于 900 秒,不符合預(yù)期,還是很讓人疑惑的。由于當(dāng)時(shí)大家認(rèn)為這個(gè)看起來比原問題還要嚴(yán)重,且通過 socketTimeout 可以規(guī)避掉,所以就沒在細(xì)究原因。到此,排查工作就結(jié)束了,后續(xù)由 DBA 推動(dòng)各應(yīng)用配置兩個(gè)超時(shí)參數(shù),這個(gè)事情告一段落。
4. 再次探索
在我準(zhǔn)備寫這篇文章前的一周,我花了一些時(shí)間重新看了一下之前的排查文檔和錯(cuò)誤日志,有個(gè)問題始終圍繞在我的腦海里,不得其解。業(yè)務(wù)日志里生產(chǎn)者和部分消費(fèi)者線程拋出的異常信息里均包含 "Connection reset",而非前面復(fù)現(xiàn)過程中出現(xiàn)的 "Read timed out"。很顯然連接被重置和連接超時(shí)不是同一種情況,那么問題出在了哪里呢?是不是我們所復(fù)現(xiàn)的環(huán)境與阿里云 RDS 有什么一樣的地方,導(dǎo)致復(fù)現(xiàn)結(jié)果與實(shí)際不符合。于是我查閱了一些和阿里云 RDS 相關(guān)的資料,有一張架構(gòu)圖吸引了我。

圖23:阿里云 RDS 高可用架構(gòu);來源:阿里云RDS技術(shù)白皮書
從這張圖里可以看出,我們搭建的復(fù)現(xiàn)環(huán)境缺少了 SLB,但 SLB 只是一個(gè)負(fù)載均衡,難道它會(huì)中斷連接?答案是,我不知道。于是又去找了一些資料了解在什么情況下會(huì)產(chǎn)生 RST 包。情況比較多,部分如下:
- 目標(biāo)端口未監(jiān)聽
- 通信雙方中的一方機(jī)器掉電重啟,本質(zhì)上也是目標(biāo)端口未監(jiān)聽
- 通信路徑中存在防火墻,連接被防火墻策略中斷
- 服務(wù)端監(jiān)聽隊(duì)列滿了,無法再接受新的連接。當(dāng)然服務(wù)端也可以直接丟棄掉 SYN 包,讓客戶端重試
- TCP 緩沖區(qū)溢出
了解了 RST 產(chǎn)生的幾種情況,我們?cè)賴L試推理一下阿里云 RDS 在發(fā)生類似故障后,會(huì)執(zhí)行什么策略。考慮到他們的技術(shù)人員也要排查問題,因此最可能的策略是僅將故障機(jī)從 SLB 上摘除,故障機(jī)器不重啟,保留現(xiàn)場(chǎng)。如果是這樣,那么故障機(jī)器并不會(huì)發(fā)送 RST 數(shù)據(jù)包。其他策略,比如殺掉 MySQL 進(jìn)程或者讓故障機(jī)關(guān)機(jī),都會(huì)發(fā)送 FIN 數(shù)據(jù)包正常關(guān)閉連接,這個(gè)我抓包驗(yàn)證過。排查到到這里,思路又?jǐn)嗔耍瑢?shí)在想不通哪里會(huì)在 900 多秒時(shí)發(fā)出一個(gè) RST 包出來。目前唯一能懷疑的可能就是 SLB,但是 SLB 畢竟只是個(gè)負(fù)載均衡,應(yīng)該會(huì)像防火墻那樣根據(jù)策略阻斷連接。由于沒有其他思路了,現(xiàn)在只能關(guān)注一下 SLB。由于對(duì) SLB 不熟悉,又是一通找資料,這次好像有點(diǎn)眉目了。
一開始通過 Google 搜索 SLB RST,沒找到有用的信息。考慮到 SLB 是基于 LVS 實(shí)現(xiàn)的,把 SLB 換成 LVS 繼續(xù)搜索,這次找到了一些有用的信息。通過這篇文章 負(fù)載均衡超時(shí)時(shí)間 了解到阿里云 SLB 在連接空閑超過設(shè)定值后,會(huì)中斷連接。于是又找到 SLB 的官方文檔,在一個(gè) FAQ 里找到了期望的信息。

圖24:阿里云官方文檔關(guān)于負(fù)載均衡 FAQ
現(xiàn)在考慮這種情況,故障機(jī)器底層網(wǎng)絡(luò)并沒問題,但處于應(yīng)用層的 MySQL 處于僵死狀態(tài),不響應(yīng)客戶端請(qǐng)求。當(dāng) TCP 連接空閑時(shí)間超過 900 秒后,SLB 客戶端發(fā)送了一個(gè) RST 斷開連接。看到這句話時(shí)非常開心,于是我在阿里云買了兩臺(tái) ECS 和一個(gè) SLB 驗(yàn)證了一下,SLB 的超時(shí)時(shí)間保持默認(rèn)值 900 秒。使用 nc 工具在一臺(tái) ECS 上啟動(dòng)一個(gè) TCP 服務(wù)器,在另一臺(tái)機(jī)器上,同樣可以使用 nc 命令連接這個(gè)服務(wù)器。只不過我們不能直連,而是同通過 SLB 連接。示意圖如下:

圖25:SLB 驗(yàn)證環(huán)境
環(huán)境搭建好后,抓包驗(yàn)證了一下。

圖26:SLB 超時(shí)機(jī)制驗(yàn)證
到這里我已經(jīng)拿到了想要的結(jié)果,目前似乎可以下結(jié)論說我們的應(yīng)用在卡住900多秒后,被 SLB 發(fā)送 RST 斷開連接了。但在后續(xù)的驗(yàn)證中發(fā)現(xiàn),連接空閑時(shí),RDS 的 TCP 層開啟了 keepalive 機(jī)制,每隔一分鐘發(fā)一個(gè)數(shù)據(jù)包做連接保活,此時(shí) SLB 不會(huì)主動(dòng)斷開連接。除非故障機(jī)器被隔離了,無法與 SLB 通信。排查到這里,基本放棄治療了。如果 RST 包是 SLB 發(fā)出的,連接應(yīng)該處于真正空閑狀態(tài),不存在保活的數(shù)據(jù)包。由于沒有當(dāng)時(shí)的抓包數(shù)據(jù),加上對(duì)阿里云內(nèi)部故障機(jī)器處理機(jī)制不了解,目前沒法給出更合理的結(jié)論了。姑且先用這個(gè)結(jié)論”搪塞“一下,也歡大家集思廣益,一起交流學(xué)習(xí)。
5. 總結(jié)與思考
本次故障排查耗時(shí)非常長(zhǎng),也花費(fèi)了我很多精力。盡管如此,還是沒有找到最終原因,感覺比較遺憾。不過不管結(jié)果怎么樣,總的來說,這次故障的排查過程讓我受益良多。一方面學(xué)到了很多知識(shí),另一方面也發(fā)現(xiàn)了一些不足。下面簡(jiǎn)單對(duì)這次故障進(jìn)行總結(jié)。
首先,這次的故障偶發(fā)性非常大,是公司使用阿里云服務(wù)幾年來第一次出現(xiàn)這樣的情況。其次,MySQL 服務(wù)端故障原因也比較復(fù)雜,根據(jù)阿里云技術(shù)的回復(fù),觸發(fā)主備切換是因?yàn)?RDS 所在的物理機(jī)文件系統(tǒng)檢查有異常。因此對(duì)我們來說,復(fù)現(xiàn)的成本也非常高。同時(shí),本次故障和網(wǎng)絡(luò)的關(guān)系很密切,但是很遺憾,我們沒有當(dāng)時(shí)的抓包數(shù)據(jù)。加上故障復(fù)現(xiàn)成本太高,且未必能 100% 復(fù)現(xiàn),導(dǎo)致這份關(guān)鍵的信息缺失。進(jìn)而導(dǎo)致我們不清楚底層的通信情況是怎樣的,比如有沒有發(fā)生重傳,服務(wù)端有沒有發(fā)送 TCP 保活數(shù)據(jù)包等。最后,在前面幾個(gè)因素的作用下,我們只能通過收集各種信息,并結(jié)合故障現(xiàn)象進(jìn)行猜想,然后逐一驗(yàn)證猜想的合理性。當(dāng)然限于我們的知識(shí)邊界,可能還有很多情況我們沒有考慮到,或者已有的猜想存在明顯不合理之處,也歡迎大家指正。
在這次的排查問題過程中,由于個(gè)人經(jīng)驗(yàn)不足,也暴露了很多問題。文章的最后同樣做下總結(jié),希望能給大家提供一些參考。
- 排查初期沒有廣泛收集信息,此時(shí)無論是做的猜想還是下的結(jié)論都是不可靠的
- 過于關(guān)注某些故障現(xiàn)象,導(dǎo)致陷入了細(xì)節(jié),沒能從整體進(jìn)行審視。不但做了很多無用功,也沒得到結(jié)果
- 計(jì)算機(jī)網(wǎng)絡(luò)知識(shí)深度不足,對(duì)一些明顯現(xiàn)象視而不見,同時(shí)也做了一些錯(cuò)誤猜想。后續(xù)需要重點(diǎn)補(bǔ)充這方面的知識(shí)
- 忽略了一些重要的差異,復(fù)現(xiàn)過程中出現(xiàn)的現(xiàn)象是超時(shí),而實(shí)際情況是連接被重置,這個(gè)差異當(dāng)時(shí)沒有深究
- 真相只有一個(gè),如果有些現(xiàn)象無法得到合理解釋,就說明問題的根源仍未找到,此時(shí)不要強(qiáng)行解釋
本篇文章到此結(jié)束,感謝閱讀。
參考內(nèi)容
- Linux TCP_RTO_MIN, TCP_RTO_MAX and the tcp_retries2
- ip-sysctl.txt
- 聊一聊重傳次數(shù)
- 你所需要掌握的問題排查知識(shí)
- 阿里云云數(shù)據(jù)庫 RDS 版技術(shù)白皮書
- 負(fù)載均衡超時(shí)問題
- 阿里云負(fù)載均衡服務(wù)FAQ
- TCP RESET/RST Reasons
本文在知識(shí)共享許可協(xié)議 4.0 下發(fā)布,轉(zhuǎn)載請(qǐng)注明出處
作者:田小波
原創(chuàng)文章優(yōu)先發(fā)布到個(gè)人網(wǎng)站,歡迎訪問:https://www.tianxiaobo.com

本作品采用知識(shí)共享署名-非商業(yè)性使用-禁止演繹 4.0 國(guó)際許可協(xié)議進(jìn)行許可。

浙公網(wǎng)安備 33010602011771號(hào)