天天看點

資料庫故障引發的“血案”

标題聽起來很聳人聽聞,不過确實沒有誇大的意思,對于我們來說确實算得上”血案“了。這個問題最終導緻了某個底層的核心應用15分鐘内不可用,間接導緻上層很多應用也出現了問題,尤其是一些支付相關的業務也出現了不可用情況。由于故障影響較大,該故障在内部定級很高。故障排查過程也算是一波三折,中間的槽點也比較多,特别是對網絡比較了解的大佬能一眼看出來問題。這個故障的排查工作我也深度參與了,這裡做一下總結,希望能給大家一些參考。

本文約 7000 字,配圖 26 張。文章相對比較長,是以這裡對文章結構做些介紹。本篇文章分為5個章節,各章節内容概括如下:

故障現象:本章對故障現象進行了介紹,在閱讀後續内容前,需先搞清楚故障現象

故障排查過程:本章介紹了故障排查過程,并給出了初步結論。

故障複現:本章基于故障排查結論,針對性的進行了故障複現和驗證,并給出了故障的處理措施

再次探索:重新對故障排查過程進行審視,并針對其中疑點再次進行探索,嘗試尋找”真相“

總結:本章對故障和排查過程中存在的一些問題進行了回顧與總結

需要說明的是,為了降低圖檔大小,一些異常棧資訊被删除了,但核心調用都在。

4月的某個周日下午2點前後,一個核心應用出現大量的報警,但是一小會後又自動恢複了,從監控上看故障持續時間約為15分鐘。翻看了業務日志,發現裡面有很多 druid 相關的報錯,看起來像是 druid 出問題了。

資料庫故障引發的“血案”

圖1:業務線程大量抛出擷取連接配接逾時異常

資料庫故障引發的“血案”

圖2:druid 連接配接生産者線程抛出網絡異常

後來從 DBA 那邊得知,阿裡雲 RDS 由于實體機發生故障,在13:57 進行了自動主備切換。由于 RDS 主備切換時間與我們的應用發生故障的時間很接近,是以初步判斷該故障和阿裡雲 RDS 切換有關。從現象上看,阿裡雲 RDS 執行主備切換後,我們的應用似乎沒有切換成功,仍然連接配接到了故障機上。由于 DBA 之前也做過很多次主備切換演練,一直都沒發生過什麼事情,是以這個問題在當時看起來還是挺費解的。

以上就是故障的背景和現象,下面開始分析故障原因。

在展開分析前,先給大家介紹一下 druid 的并發模型,做一些技術鋪墊。

druid 資料源使用生産者消費者模型維護連接配接池,當連接配接池中沒有連接配接時,消費者線程會通知生産者線程建立連接配接。生産者建立好連接配接後,會将連接配接放到池中,并通知消費者線程取連接配接。如果消費者線程在設定時間沒沒取到連接配接,會抛出一個逾時異常。

資料庫故障引發的“血案”

圖3:druid 并發模型

注意,生産者線程是單線程,如果這個線程在某些情況下阻塞住,會造成大量的消費者線程無法擷取到連接配接。

這個問題最早是我接手排查的,當時很多資訊都還沒有,隻有異常日志。剛開始排查的時候,我翻看了其中一台機器上的日志,發現日志中隻有大量的 GetConnectionTimeoutException 異常,沒有 druid 生産者線程抛出的異常。

資料庫故障引發的“血案”

圖4:消費者線程抛出異常

在消費者線程抛出的異常資訊裡,包含了兩個與生産者有關的資料,通過這兩個資料可以了解到生産者處于的狀态。第一個是 creating,表示生産者目前正在建立連接配接。第二個是 createElapseMillis,表示消費者逾時傳回時,生産者建立連接配接所消耗的時間。上圖中,createElapseMillis 值約為900秒,這明顯是有問題的,說明生産者線程應該是被阻塞住了。是以根據這個資訊,我給出了一個初步結論:

生産者線程被卡住,很可能的原因是在建立連接配接時沒有配置逾時時間,可以通過在資料庫 URL 後面追加一個 connectTimeout 參數解決這個問題。

排查到這裡好像也能解釋通,但是這裡有很多疑問沒有解決:到底是在哪個方法上卡住了?配置這個參數是否真的有用,能否複現驗證?不回答掉這些問題,這個故障排查結論顯然不能說服人。是以後續有更多人參與進來排查,收集到的資訊也越來越多。

這個時候,我們的 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

排查到這裡,很多東西都能解釋通了,似乎可以“結案”了。可是情況真的如此嗎?由于沒有當時的抓包資料,大家還是沒法确定是不是這個原因。于是接下來,我按照這個排查結論進行了複現。

為了進行較為準确的複現,我們在一台與線上配置相同的 ECS 上部署業務應用。在内網的另一台 ECS 上搭建了一個 MySQL 服務,并把線上資料同步到這個資料庫中。由于我們沒法制造 MySQL 實體機故障,是以我們通過 iptables 配置防火牆政策來模拟因機器故障導緻的網絡層故障,比如不響應用戶端請求。最後我們通過 arthas 對 druid 生産者線程進行監控,觀測連接配接建立耗時情況。

在展開後續内容前,先介紹一下 MySQL 驅動與服務端建立連接配接的過程。示意圖如下:

資料庫故障引發的“血案”

圖8:MySQL 用戶端與服務端通信過程

這裡簡單講解下,業務應用在建立一個 MySQL 資料庫連接配接時,首先要完成 TCP 三次握手,待 TCP 連接配接建立完畢後,再基于 TCP 連接配接進行應用層的握手。主要是互換一些資訊,以及登入認證。服務端握手資訊主要傳回的是伺服器的版本,伺服器接受的登入認證方式,以及其他用于認證的資料。用戶端收到資料庫的握手資訊後,将使用者名和密碼加密後進行登入認證,随後服務端傳回認證結果。下面我們抓包看一下雙方的互動過程。

用戶端 ip: 172.***.***.141

服務端 ip: 172.***.***.251

在用戶端機器上進行抓包,指令如下:

抓包結果如下:

資料庫故障引發的“血案”

圖9:MySQL 連接配接建立過程抓包結果1

資料庫故障引發的“血案”

圖10:MySQL 連接配接建立過程抓包結果2

我們後續将使用 Version 作為伺服器握手封包段的特征字元串,根據這個特征配置防火牆規則。

本節,我們除了要驗證故障出現的可能場景,還要驗證我們的解決辦法是否有效。在進行複現前,我們要修改一下 druid 的配置,保證 druid 可以快速關閉空閑連接配接,友善驗證連接配接建立過程。

根據生産者線程抛出的異常顯示,生産者線程是在與 MySQL 服務端進行應用層握手時卡住的,異常日志如下:

資料庫故障引發的“血案”

圖11: druid 生産者線程抛出的異常

根據這個報錯日志我們可以判斷出問題是出在了 TCP 連接配接建立後,MySQL 應用層握手期間時。之是以可以這麼肯定,是因為代碼都到了應用層握手階段,TCP 層連接配接的建立肯定是完成了,否則應該會出現類似無法連接配接的錯誤。是以我們隻需要驗證 MySQL 用戶端與服務端進行應用層握手失敗的場景即可,不過我們可以稍微多驗證一些其他場景,增加對底層網絡行為的了解。下面我們進行三個場景的模拟:

場景一:服務端不響應用戶端 SYN 封包段,TCP 無法完成三次握手

場景二:TCP 連接配接可以正常建立,但是服務端不與用戶端進行應用層握手

場景三:連接配接池中已經建立好的連接配接無法與服務端通信,導緻消費者線程被阻塞

預期現象:TCP 資料包被丢棄,用戶端不停重試。druid 生産者線程被阻塞住,資料庫連接配接無法建立

步驟一:場景模拟

登入到 MySQL 伺服器,設定防火牆規則,丢棄所有來自用戶端的資料包

步驟二:觸發資料庫通路,觀察現象

登入業務機器,使用 arthas 觀察 druid 生産者線程執行情況,指令如下:

觸發一個資料庫通路,由于連接配接池中沒有連接配接,druid 會去建立一個連接配接。現象如下:

資料庫故障引發的“血案”

圖12:底層網絡故障,druid 建立連接配接耗時情況

可以看出,TCP 連接配接無法建立時,druid 的 DruidAbstractDataSource#createPhysicalConnection 方法會消耗掉約127秒,且會抛出異常。取消掉服務端的防火牆規則:觀察正常情況下,建立連接配接耗時情況:

資料庫故障引發的“血案”

圖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.

來源:ip-sysctl.txt

注意最後一句話,與我們使用 arthas trace 指令得到的結果基本是一緻的。下面再抓個包觀察一下:

資料庫故障引發的“血案”

圖14:TCP SYN 重傳情況

如上,第一個包是用戶端初始的握手包,後面6個包都是進行重試。第8個包發出時,時間正好過去了 127 秒,與核心參數說明是一緻的。到這裡,關于 TCP 連接配接無法建立成功的問題就說清楚了。由于我們的應用被卡住了 900 多秒,是以顯然可以排除 TCP 握手失敗的情況了。不過雖然原因不是這個,但如果 druid 生産者線程被卡住 127 秒,那也是相當危險的。如何預防呢?

預防連接配接逾時問題

通過配置 connectTimeout 參數,可以降低 TCP SYN 重試時間,配置如下:

再發起一個資料庫請求驗證一下配置是否有效。

資料庫故障引發的“血案”

圖15:配置 connectTimeout 參數後,druid 生産者線程逾時情況

如上圖,druid 生産者線程調用 DruidAbstractDataSource#createPhysicalConnection 消耗了 3 秒,符合預期,說明配置有效。用戶端會抛出的異常如下:

資料庫故障引發的“血案”

圖16:用戶端抛出的異常細節

這次我們來模拟底層網絡正常,但是應用層不正常的情況,即 MySQL 伺服器不與用戶端進行握手。

預期現象:druid 生産者線程卡住約900秒後報錯傳回

步驟一:模拟場景

在 MySQL 伺服器上配置防火牆規則,禁止 MySQL 握手資料包流出。

檢視防火牆規則

資料庫故障引發的“血案”

圖17:防火牆規則清單

步驟二:觀察現象

這次我們通過消費者線程抛出的異常日志來觀察 druid 生産者線程的建立時間,異常日志如下:

資料庫故障引發的“血案”

圖18:消費者線程異常日志

如上,消費者線程的異常資訊裡顯示生産者線程以及被阻塞了 1247 秒,且這個值随着時間的推移越來越長。遠遠超過了 900 秒,與預期不符合,原因沒有深入探究。不過,我們似乎發現了比原故障更嚴重的問題,排查到這裡好像可以停下腳步了。

預防 MySQL 應用層握手逾時

由于 connectTimeout 僅作用在網絡層,對應用層的通信無效,是以這次我們要換個參數了。這次我們使用的參數是 socketTimeout,配置如下:

設定 socketTimeout 參數值為 5000 毫秒,驗證服務端不與用戶端握手情況下,用戶端能否在 5 秒後逾時傳回。arthas 監控如下:

資料庫故障引發的“血案”

圖19:arthas trace 監控

結果符合預期,druid 生産者線程确實在 5 秒後報錯傳回了,錯誤資訊如下:

資料庫故障引發的“血案”

圖20:druid 生産者線程逾時傳回情況

如上,通過配置 socketTimeout 可以保證 druid 在服務端不進行握手的情況下逾時傳回。

最後一個場景用于複現在 MySQL 實體機出故障,不響應用戶端的 SQL 請求。

預期現象:用戶端不停重試,直至 924 秒後逾時傳回

要模拟這種場景,可以在 MySQL 服務端丢棄掉來自用戶端的所有資料包,防火牆配置參考上面的内容。直接看現象吧。

資料庫故障引發的“血案”

圖21:消費者線程逾時傳回

如上,消費者線程逾時傳回時間與 924 秒非常接近,基本可以判定多次重試失敗後,逾時傳回了。抓包佐證一下:

資料庫故障引發的“血案”

圖22:TCP 連接配接重試情況

最後一個資料包發出的時間證明了我們的判斷是對的。從上面的抓包結果可以看出,總共進行了16次重試。前面說過,TCP 非 SYN 重試受核心參數 ipv4.tcp_retries2 影響,該參數值預設為 15,為什麼這裡進行了 16 次重試呢?這裡簡單說明一下吧,這裡的 15 是用來計算逾時總時長的,并不代表重傳次數,更詳細的解釋大家 STFW。

場景三的預防方式與場景二相同,都是通過配置 socketTimeout,就不贅述了。

到此,整個的複現過程就結束了。通過對故障進行複現,似乎證明了我們之前的排查結果是正确的。與此同時,我們也對 connectTimeout 和 socketTimeout 兩個配置的有效性進行了驗證,結果也是符合預期的。但是複現過程中,生産者被卡住的時間遠遠長于 900 秒,不符合預期,還是很讓人疑惑的。由于當時大家認為這個看起來比原問題還要嚴重,且通過 socketTimeout 可以規避掉,是以就沒在細究原因。到此,排查工作就結束了,後續由 DBA 推動各應用配置兩個逾時參數,這個事情告一段落。

在我準備寫這篇文章前的一周,我花了一些時間重新看了一下之前的排查文檔和錯誤日志,有個問題始終圍繞在我的腦海裡,不得其解。業務日志裡生産者和部分消費者線程抛出的異常資訊裡均包含 "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 發出的,連接配接應該處于真正空閑狀态,不存在保活的資料包。由于沒有當時的抓包資料,加上對阿裡雲内部故障機器處理機制不了解,目前沒法給出更合理的結論了。姑且先用這個結論”搪塞“一下,也歡大家集思廣益,一起交流學習。

本次故障排查耗時非常長,也花費了我很多精力。盡管如此,還是沒有找到最終原因,感覺比較遺憾。不過不管結果怎麼樣,總的來說,這次故障的排查過程讓我受益良多。一方面學到了很多知識,另一方面也發現了一些不足。下面簡單對這次故障進行總結。

首先,這次的故障偶發性非常大,是公司使用阿裡雲服務幾年來第一次出現這樣的情況。其次,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 國際許可協定進行許可。

繼續閱讀