標題聽起來很聳人聽聞，不過確實沒有誇大的意思，對於我們來說確實算得上”血案“了。這個問題最終導致了某個底層的核心應用15分鍾內不可用，間接導致上層很多應用也出現了問題，尤其是一些支付相關的業務也出現了不可用情況。由於故障影響較大，該故障在內部定級很高。故障排查過程也算是一波三折，中間的槽點也比較多，特別是對網絡比較了解的大佬能一眼看出來問題。這個故障的排查工作我也深度參與了，這里做一下總結，希望能給大家一些參考。
0. 文章導讀
本文約 7000 字，配圖 26 張。文章相對比較長，因此這里對文章結構做些介紹。本篇文章分為5個章節，各章節內容概括如下：
- 故障現象：本章對故障現象進行了介紹，在閱讀后續內容前，需先搞清楚故障現象
- 故障排查過程：本章介紹了故障排查過程，並給出了初步結論。
- 故障復現：本章基於故障排查結論，針對性的進行了故障復現和驗證，並給出了故障的處理措施
- 再次探索：重新對故障排查過程進行審視，並針對其中疑點再次進行探索，嘗試尋找”真相“
- 總結：本章對故障和排查過程中存在的一些問題進行了回顧與總結
需要說明的是，為了降低圖片大小，一些異常棧信息被刪除了，但核心調用都在。
1. 故障現象
4月的某個周日下午2點前后，一個核心應用出現大量的報警，但是一小會后又自動恢復了，從監控上看故障持續時間約為15分鍾。翻看了業務日志，發現里面有很多 druid 相關的報錯，看起來像是 druid 出問題了。
圖1：業務線程大量拋出獲取連接超時異常
圖2：druid 連接生產者線程拋出網絡異常
后來從 DBA 那邊得知，阿里雲 RDS 由於物理機發生故障，在13:57 進行了自動主備切換。由於 RDS 主備切換時間與我們的應用發生故障的時間很接近，因此初步判斷該故障和阿里雲 RDS 切換有關。從現象上看，阿里雲 RDS 執行主備切換后，我們的應用似乎沒有切換成功，仍然連接到了故障機上。由於 DBA 之前也做過很多次主備切換演練，一直都沒發生過什么事情，所以這個問題在當時看起來還是挺費解的。
以上就是故障的背景和現象，下面開始分析故障原因。
2. 故障排查過程
在展開分析前，先給大家介紹一下 druid 的並發模型，做一些技術鋪墊。
2.1 背景知識介紹
druid 數據源使用生產者消費者模型維護連接池，當連接池中沒有連接時，消費者線程會通知生產者線程創建連接。生產者創建好連接后，會將連接放到池中，並通知消費者線程取連接。如果消費者線程在設定時間沒沒取到連接，會拋出一個超時異常。
圖3：druid 並發模型
注意，生產者線程是單線程，如果這個線程在某些情況下阻塞住，會造成大量的消費者線程無法獲取到連接。
2.2 排查過程
2.2.1 初步排查
這個問題最早是我接手排查的，當時很多信息都還沒有，只有異常日志。剛開始排查的時候，我翻看了其中一台機器上的日志，發現日志中只有大量的 GetConnectionTimeoutException 異常，沒有 druid 生產者線程拋出的異常。
圖4：消費者線程拋出異常
在消費者線程拋出的異常信息里，包含了兩個與生產者有關的數據，通過這兩個數據可以了解到生產者處於的狀態。第一個是 creating，表示生產者當前正在創建連接。第二個是 createElapseMillis，表示消費者超時返回時，生產者創建連接所消耗的時間。上圖中，createElapseMillis 值約為900秒，這明顯是有問題的，說明生產者線程應該是被阻塞住了。因此根據這個信息，我給出了一個初步結論：
生產者線程被卡住，很可能的原因是在創建連接時沒有配置超時時間，可以通過在數據庫 URL 后面追加一個 connectTimeout 參數解決這個問題。
排查到這里好像也能解釋通，但是這里有很多疑問沒有解決：到底是在哪個方法上卡住了？配置這個參數是否真的有用，能否復現驗證？不回答掉這些問題，這個故障排查結論顯然不能說服人。因此后續有更多人參與進來排查，收集到的信息也越來越多。
2.2.2 深入排查
這個時候，我們的 DBA 開始找阿里雲技術支持溝通，得到的答復 RDS 物理機出現了故障，觸發了自動主備切換機制。另一方面，其他同事詳細閱讀了更多機器的錯誤日志，發現了生產者線程也拋出了異常。
圖5：druid 生產線線程拋出網絡異常
奇怪的是，其中有兩台機器的日志里找不到生產者的異常。后來詢問了應用負責人，才了解到他在 14:10 重啟過應用，剩余機器還沒來得及重啟，服務就已經恢復了。不巧的是，我剛開始排查的時候，查看的日志正是被重啟過的機器的日志。這里也凸顯排查問題時，廣泛收集信息的重要性。除了生產者線程拋出了這個異常，部分消費者線程也拋出了同樣的異常：
圖6：消費者線程拋出網絡異常
如上，生產者和部分消費者線程都是在卡住900多秒后拋出異常，通過查閱 TCP 相關的資料，一起排查的同事認為這個時間應該是底層網絡最大的超時時間導致的。因此推斷 MySQL 物理機發生故障后，不再響應客戶端的任何數據包。客戶端機器底層網絡在經過多次重試后失敗后，自己關閉了連接，上層應用拋出 SocketException。通過資料，我們了解到 net.ipv4.tcp_retries2 內核參數用於控制 TCP 的重傳。Linux 官方文檔有相關說明：
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 超時重傳情況；圖片來源：Marco Pracucci
排查到這里，很多東西都能解釋通了，似乎可以“結案”了。可是情況真的如此嗎？由於沒有當時的抓包數據，大家還是沒法確定是不是這個原因。於是接下來，我按照這個排查結論進行了復現。
3. 故障復現
3.1 准備工作
為了進行較為准確的復現，我們在一台與線上配置相同的 ECS 上部署業務應用。在內網的另一台 ECS 上搭建了一個 MySQL 服務，並把線上數據同步到這個數據庫中。由於我們沒法制造 MySQL 物理機故障，因此我們通過 iptables 配置防火牆策略來模擬因機器故障導致的網絡層故障，比如不響應客戶端請求。最后我們通過 arthas 對 druid 生產者線程進行監控，觀測連接創建耗時情況。
3.2 背景知識介紹
在展開后續內容前，先介紹一下 MySQL 驅動與服務端建立連接的過程。示意圖如下：
圖8：MySQL 客戶端與服務端通信過程
這里簡單講解下，業務應用在建立一個 MySQL 數據庫連接時，首先要完成 TCP 三次握手，待 TCP 連接建立完畢后，再基於 TCP 連接進行應用層的握手。主要是互換一些信息，以及登錄認證。服務端握手信息主要返回的是服務器的版本，服務器接受的登錄認證方式，以及其他用於認證的數據。客戶端收到數據庫的握手信息后，將用戶名和密碼加密后進行登錄認證，隨后服務端返回認證結果。下面我們抓包看一下雙方的交互過程。
客戶端 ip: 172.***.***.141
服務端 ip: 172.***.***.251
在客戶端機器上進行抓包，命令如下：
tcpdump -i eth0 host 172.***.***.251 -w mysql.pcap
抓包結果如下：
圖9：MySQL 連接建立過程抓包結果1
圖10：MySQL 連接建立過程抓包結果2
我們后續將使用 Version 作為服務器握手報文段的特征字符串，根據這個特征配置防火牆規則。
3.3 故障復現
本節，我們除了要驗證故障出現的可能場景，還要驗證我們的解決辦法是否有效。在進行復現前，我們要修改一下 druid 的配置，保證 druid 可以快速關閉空閑連接，方便驗證連接創建過程。
<bean id="dataSource" class="com.alibaba.druid.pool.DruidDataSource" init-method="init" destroy-method="close">
<!-- 不配置超時時間，與線上配置保持一致 -->
<property name="url" value="jdbc:mysql://172.***.***.251:3306/***db" />
<!-- 最小空閑連接數 -->
<property name="minIdle" value="0"/>
<!-- 初始連接數 -->
<property name="initialSize" value="0"/>
<!-- 每隔1.5秒檢測連接是否需要被驅逐 -->
<property name="timeBetweenEvictionRunsMillis" value="1500" />
<!-- 最小驅逐時間，連接空閑時間一旦超過這個時間，就會被關閉 -->
<property name="minEvictableIdleTimeMillis" value="3000" />
</bean>
3.3.1 故障場景推斷
根據生產者線程拋出的異常顯示，生產者線程是在與 MySQL 服務端進行應用層握手時卡住的，異常日志如下：
圖11: druid 生產者線程拋出的異常
根據這個報錯日志我們可以判斷出問題是出在了 TCP 連接建立后，MySQL 應用層握手期間時。之所以可以這么肯定，是因為代碼都到了應用層握手階段，TCP 層連接的建立肯定是完成了，否則應該會出現類似無法連接的錯誤。因此我們只需要驗證 MySQL 客戶端與服務端進行應用層握手失敗的場景即可，不過我們可以稍微多驗證一些其他場景，增加對底層網絡行為的了解。下面我們進行三個場景的模擬：
場景一：服務端不響應客戶端 SYN 報文段，TCP 無法完成三次握手
場景二：TCP 連接可以正常建立，但是服務端不與客戶端進行應用層握手
場景三：連接池中已經建立好的連接無法與服務端通信，導致消費者線程被阻塞
3.3.2 故障復現與驗證
3.3.2.1 故障場景一
預期現象：TCP 數據包被丟棄，客戶端不停重試。druid 生產者線程被阻塞住，數據庫連接無法建立
步驟一：場景模擬
登錄到 MySQL 服務器，設置防火牆規則，丟棄所有來自客戶端的數據包
iptables -I INPUT -s 172.***.***.141 -j DROP
步驟二：觸發數據庫訪問，觀察現象
登錄業務機器，使用 arthas 觀察 druid 生產者線程執行情況，命令如下：
trace com.alibaba.druid.pool.DruidAbstractDataSource createPhysicalConnection -n 1000 -j
觸發一個數據庫訪問，由於連接池中沒有連接，druid 會去創建一個連接。現象如下：
圖12：底層網絡故障，druid 新建連接耗時情況
可以看出，TCP 連接無法建立時，druid 的 DruidAbstractDataSource#createPhysicalConnection 方法會消耗掉約127秒，且會拋出異常。取消掉服務端的防火牆規則：觀察正常情況下，新建連接耗時情況：
iptables -D INPUT -s 172.***.***.141 -j DROP
圖13：正常情況下，druid 新建連接耗時情況
如上，正常情況和異常情況耗時對比還是很明顯的，那這 127 秒耗時是如何來的呢？下面分析一下。
異常情況分析
TCP 在建立連接過程中，如果第一個 SYN 報文段丟失（沒收到另一端的 ACK 報文），Linux 系統會進行重試，重試一定次數后終止。初始的 SYN 重試次數受內核參數 tcp_syn_retries，該參數默認值為6。內核參數說明如下：
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 命令得到的結果基本是一致的。下面再抓個包觀察一下：
圖14：TCP SYN 重傳情況
如上，第一個包是客戶端初始的握手包，后面6個包都是進行重試。第8個包發出時，時間正好過去了 127 秒，與內核參數說明是一致的。到這里，關於 TCP 連接無法創建成功的問題就說清楚了。由於我們的應用被卡住了 900 多秒，因此顯然可以排除 TCP 握手失敗的情況了。不過雖然原因不是這個，但如果 druid 生產者線程被卡住 127 秒，那也是相當危險的。如何預防呢？
預防連接超時問題
通過配置 connectTimeout 參數，可以降低 TCP SYN 重試時間，配置如下：
jdbc:mysql://172.***.***.251:3306/***db?connectTimeout=3000
再發起一個數據庫請求驗證一下配置是否有效。
圖15：配置 connectTimeout 參數后，druid 生產者線程超時情況
如上圖，druid 生產者線程調用 DruidAbstractDataSource#createPhysicalConnection 消耗了 3 秒，符合預期，說明配置有效。客戶端會拋出的異常如下：
圖16：客戶端拋出的異常細節
3.3.2.2 故障場景二
這次我們來模擬底層網絡正常，但是應用層不正常的情況，即 MySQL 服務器不與客戶端進行握手。
預期現象：druid 生產者線程卡住約900秒后報錯返回
步驟一：模擬場景
在 MySQL 服務器上配置防火牆規則，禁止 MySQL 握手數據包流出。
# 使用 iptables 的 string 模塊進行字符串匹配
iptables -I OUTPUT -m string --algo bm --string "5.7.34-log" -j DROP
查看防火牆規則
圖17：防火牆規則列表
步驟二：觀察現象
這次我們通過消費者線程拋出的異常日志來觀察 druid 生產者線程的創建時間，異常日志如下：
圖18：消費者線程異常日志
如上，消費者線程的異常信息里顯示生產者線程以及被阻塞了 1247 秒，且這個值隨着時間的推移越來越長。遠遠超過了 900 秒，與預期不符合，原因沒有深入探究。不過，我們似乎發現了比原故障更嚴重的問題，排查到這里好像可以停下腳步了。
預防 MySQL 應用層握手超時
由於 connectTimeout 僅作用在網絡層，對應用層的通信無效，所以這次我們要換個參數了。這次我們使用的參數是 socketTimeout，配置如下：
jdbc:mysql://172.***.***.251:3306/***db?connectTimeout=3000&socketTimeout=5000
設定 socketTimeout 參數值為 5000 毫秒，驗證服務端不與客戶端握手情況下，客戶端能否在 5 秒后超時返回。arthas 監控如下：
圖19：arthas trace 監控
結果符合預期，druid 生產者線程確實在 5 秒后報錯返回了，錯誤信息如下：
圖20：druid 生產者線程超時返回情況
如上，通過配置 socketTimeout 可以保證 druid 在服務端不進行握手的情況下超時返回。
3.3.2.3 故障場景三
最后一個場景用於復現在 MySQL 物理機出故障，不響應客戶端的 SQL 請求。
預期現象：客戶端不停重試，直至 924 秒后超時返回
要模擬這種場景，可以在 MySQL 服務端丟棄掉來自客戶端的所有數據包，防火牆配置參考上面的內容。直接看現象吧。
圖21：消費者線程超時返回
如上，消費者線程超時返回時間與 924 秒非常接近，基本可以判定多次重試失敗后，超時返回了。抓包佐證一下：
圖22：TCP 連接重試情況
最后一個數據包發出的時間證明了我們的判斷是對的。從上面的抓包結果可以看出，總共進行了16次重試。前面說過，TCP 非 SYN 重試受內核參數 ipv4.tcp_retries2 影響，該參數值默認為 15，為什么這里進行了 16 次重試呢？這里簡單說明一下吧，這里的 15 是用來計算超時總時長的，並不代表重傳次數，更詳細的解釋大家 STFW。
場景三的預防方式與場景二相同，都是通過配置 socketTimeout，就不贅述了。
3.4 小結
到此，整個的復現過程就結束了。通過對故障進行復現，似乎證明了我們之前的排查結果是正確的。與此同時，我們也對 connectTimeout 和 socketTimeout 兩個配置的有效性進行了驗證，結果也是符合預期的。但是復現過程中，生產者被卡住的時間遠遠長於 900 秒，不符合預期，還是很讓人疑惑的。由於當時大家認為這個看起來比原問題還要嚴重，且通過 socketTimeout 可以規避掉，所以就沒在細究原因。到此，排查工作就結束了，后續由 DBA 推動各應用配置兩個超時參數，這個事情告一段落。
4. 再次探索
在我准備寫這篇文章前的一周，我花了一些時間重新看了一下之前的排查文檔和錯誤日志，有個問題始終圍繞在我的腦海里，不得其解。業務日志里生產者和部分消費者線程拋出的異常信息里均包含 "Connection reset"，而非前面復現過程中出現的 "Read timed out"。很顯然連接被重置和連接超時不是同一種情況，那么問題出在了哪里呢？是不是我們所復現的環境與阿里雲 RDS 有什么一樣的地方，導致復現結果與實際不符合。於是我查閱了一些和阿里雲 RDS 相關的資料，有一張架構圖吸引了我。
圖23：阿里雲 RDS 高可用架構；來源：阿里雲RDS技術白皮書
從這張圖里可以看出，我們搭建的復現環境缺少了 SLB，但 SLB 只是一個負載均衡，難道它會中斷連接？答案是，我不知道。於是又去找了一些資料了解在什么情況下會產生 RST 包。情況比較多，部分如下：
- 目標端口未監聽
- 通信雙方中的一方機器掉電重啟，本質上也是目標端口未監聽
- 通信路徑中存在防火牆，連接被防火牆策略中斷
- 服務端監聽隊列滿了，無法再接受新的連接。當然服務端也可以直接丟棄掉 SYN 包，讓客戶端重試
- TCP 緩沖區溢出
了解了 RST 產生的幾種情況，我們再嘗試推理一下阿里雲 RDS 在發生類似故障后，會執行什么策略。考慮到他們的技術人員也要排查問題，因此最可能的策略是僅將故障機從 SLB 上摘除，故障機器不重啟，保留現場。如果是這樣，那么故障機器並不會發送 RST 數據包。其他策略，比如殺掉 MySQL 進程或者讓故障機關機，都會發送 FIN 數據包正常關閉連接，這個我抓包驗證過。排查到到這里，思路又斷了，實在想不通哪里會在 900 多秒時發出一個 RST 包出來。目前唯一能懷疑的可能就是 SLB，但是 SLB 畢竟只是個負載均衡，應該會像防火牆那樣根據策略阻斷連接。由於沒有其他思路了，現在只能關注一下 SLB。由於對 SLB 不熟悉，又是一通找資料，這次好像有點眉目了。
一開始通過 Google 搜索 SLB RST，沒找到有用的信息。考慮到 SLB 是基於 LVS 實現的，把 SLB 換成 LVS 繼續搜索，這次找到了一些有用的信息。通過這篇文章 負載均衡超時時間 了解到阿里雲 SLB 在連接空閑超過設定值后，會中斷連接。於是又找到 SLB 的官方文檔，在一個 FAQ 里找到了期望的信息。
圖24：阿里雲官方文檔關於負載均衡 FAQ
現在考慮這種情況，故障機器底層網絡並沒問題，但處於應用層的 MySQL 處於僵死狀態，不響應客戶端請求。當 TCP 連接空閑時間超過 900 秒后，SLB 客戶端發送了一個 RST 斷開連接。看到這句話時非常開心，於是我在阿里雲買了兩台 ECS 和一個 SLB 驗證了一下，SLB 的超時時間保持默認值 900 秒。使用 nc 工具在一台 ECS 上啟動一個 TCP 服務器，在另一台機器上，同樣可以使用 nc 命令連接這個服務器。只不過我們不能直連，而是同通過 SLB 連接。示意圖如下：
圖25：SLB 驗證環境
環境搭建好后，抓包驗證了一下。
圖26：SLB 超時機制驗證
到這里我已經拿到了想要的結果，目前似乎可以下結論說我們的應用在卡住900多秒后，被 SLB 發送 RST 斷開連接了。但在后續的驗證中發現，連接空閑時，RDS 的 TCP 層開啟了 keepalive 機制，每隔一分鍾發一個數據包做連接保活，此時 SLB 不會主動斷開連接。除非故障機器被隔離了，無法與 SLB 通信。排查到這里，基本放棄治療了。如果 RST 包是 SLB 發出的，連接應該處於真正空閑狀態，不存在保活的數據包。由於沒有當時的抓包數據，加上對阿里雲內部故障機器處理機制不了解，目前沒法給出更合理的結論了。姑且先用這個結論”搪塞“一下，也歡大家集思廣益，一起交流學習。
5. 總結與思考
本次故障排查耗時非常長，也花費了我很多精力。盡管如此，還是沒有找到最終原因，感覺比較遺憾。不過不管結果怎么樣，總的來說，這次故障的排查過程讓我受益良多。一方面學到了很多知識，另一方面也發現了一些不足。下面簡單對這次故障進行總結。
首先，這次的故障偶發性非常大，是公司使用阿里雲服務幾年來第一次出現這樣的情況。其次，MySQL 服務端故障原因也比較復雜，根據阿里雲技術的回復，觸發主備切換是因為 RDS 所在的物理機文件系統檢查有異常。因此對我們來說，復現的成本也非常高。同時，本次故障和網絡的關系很密切，但是很遺憾，我們沒有當時的抓包數據。加上故障復現成本太高，且未必能 100% 復現，導致這份關鍵的信息缺失。進而導致我們不清楚底層的通信情況是怎樣的，比如有沒有發生重傳，服務端有沒有發送 TCP 保活數據包等。最后，在前面幾個因素的作用下，我們只能通過收集各種信息，並結合故障現象進行猜想，然后逐一驗證猜想的合理性。當然限於我們的知識邊界，可能還有很多情況我們沒有考慮到，或者已有的猜想存在明顯不合理之處，也歡迎大家指正。
在這次的排查問題過程中，由於個人經驗不足，也暴露了很多問題。文章的最后同樣做下總結，希望能給大家提供一些參考。
- 排查初期沒有廣泛收集信息，此時無論是做的猜想還是下的結論都是不可靠的
- 過於關注某些故障現象，導致陷入了細節，沒能從整體進行審視。不但做了很多無用功，也沒得到結果
- 計算機網絡知識深度不足，對一些明顯現象視而不見，同時也做了一些錯誤猜想。后續需要重點補充這方面的知識
- 忽略了一些重要的差異，復現過程中出現的現象是超時，而實際情況是連接被重置，這個差異當時沒有深究
- 真相只有一個，如果有些現象無法得到合理解釋，就說明問題的根源仍未找到，此時不要強行解釋
本篇文章到此結束，感謝閱讀。
參考內容
- Linux TCP_RTO_MIN, TCP_RTO_MAX and the tcp_retries2
- ip-sysctl.txt
- 聊一聊重傳次數
- 你所需要掌握的問題排查知識
- 阿里雲雲數據庫 RDS 版技術白皮書
- 負載均衡超時問題
- 阿里雲負載均衡服務FAQ
- TCP RESET/RST Reasons
本文在知識共享許可協議 4.0 下發布，轉載請注明出處
作者：田小波
原創文章優先發布到個人網站，歡迎訪問：https://www.tianxiaobo.com
本作品采用知識共享署名-非商業性使用-禁止演繹 4.0 國際許可協議進行許可。