解Bug之路-記一次存儲故障的排查過程

解Bug之路-記一次存儲故障的排查過程

高可用真是一絲細節都不得馬虎。平時跑的好好的系統,在相應硬件出現故障時就會引發出潛在的Bug。偏偏這些故障在應用層的表現稀奇古怪,很難讓人聯想到是硬件出了問題,特別是偶發性出現的問題更難排查。今天,筆者就給大家帶來一個存儲偶發性故障的排查過程。

Bug現場

我們的積分應用由於量非常大,所以需要進行分庫分表,所以接入了我們的中間件。一直穩定運行,但應用最近確經常偶發連接建立不上的報錯。報錯如下:

GetConnectionTimeOutException

而筆者中間件這邊收到的確是:

NIOReactor - register err java.nio.channels.CloasedChannelException 

這樣的告警。整個Bug現場如下圖所示:

偶發性錯誤

之前出過類似register err這樣的零星報警,最後原因是安全掃描,並沒有對業務造成任何影響。而這一次,類似的報錯造成了業務的大量連接超時。由於封網,線上中間件和應用已經穩定在線上跑了一個多月,代碼層面沒有任何改動!突然出現的這個錯誤感覺是環境出現了某些問題。而且由於線上的應用和中間件都是集群,出問題時候都不是孤立的機器報錯,沒道理所有機器都正好有問題。如下圖所示:

開始排查是否網絡問題

遇到這種連接超時,筆者最自然的想法當然是網絡出了問題。於是找網工進行排查,
在監控裏面發現網絡一直很穩定。而且如果是網絡出現問題,同一網段的應用應該也都會報錯
才對。事實上只有對應的應用和中間件才報錯,其它的應用依舊穩穩噹噹。

又發生了兩次

就在筆者覺得這個偶發性問題可能不會再出現的時候,又開始抖了。而且是一個下午連抖了兩次。臉被打的啪啪的,算了算了,先重啟吧。重啟中間件后,以為能消停一會,沒想到半個小時之內又報了。看來今天不幹掉這個Bug是下不了班了!

開始排查日誌

事實上,筆者一開始就發現中間件有調用後端數據庫慢SQL的現象,由於比較偶發,所以將這個現象發給DBA之後就沒有繼續跟進,DBA也反饋SQL執行沒有任何異常。筆者開始認真分析日誌之後,發現一旦有 中間件的register err 必定會出現中間件調用後端數據庫的sql read timeout的報錯。
但這兩個報錯完全不是在一個線程裏面的,一個是處理前端的Reactor線程,一個是處理後端SQL的Worker線程,如下圖所示:

這兩個線程是互相獨立的,代碼中並沒有發現任何機制能讓這兩個線程互相影響。難道真是這些機器本身網絡出了問題?前端APP失敗,後端調用DB超時,怎麼看都像網絡的問題!

進一步進行排查

既然有DB(數據庫)超時,筆者就先看看調用哪個DB超時吧,畢竟後面有一堆DB。筆者突然發現,和之前的慢SQL一樣,都是調用第二個數據庫超時,而DBA那邊卻說SQL執行沒有任何異常,

筆者感覺明顯SQL執行有問題,只不過DBA是採樣而且將採樣耗時平均的,偶爾的幾筆耗時並不會在整體SQL的耗時裏面有所體現。

只能靠日誌分析了

既然找不到什麼頭緒,那麼只能從日誌入手,好好分析推理了。REACTOR線程和Worker線程同時報錯,但兩者並無特殊的關聯,說明可能是同一個原因引起的兩種不同現象。筆者在線上報錯日誌裏面進行細細搜索,發現在大量的

NIOReactor-1-RW register err java.nio.channels.CloasedChannelException

日誌中會摻雜着這個報錯:

NIOReactor-1-RW Socket Read timed out
	at XXXXXX . doCommit
	at XXXXXX Socket read timedout

這一看就發現了端倪,Reactor作為一個IO線程,怎麼會有數據庫調用呢?於是翻了翻源碼,原來,我們的中間件在處理commit/rollback這樣的操作時候還是在Reactor線程進行的!很明顯Reactor線程卡主是由於commit慢了!筆者立馬反應過來,而這個commit慢也正是導致了regsiter err以及客戶端無法創建連接的元兇。如下面所示:

由於app1的commit特別慢而卡住了reactor1線程,從而落在reactor1線程上的握手操作都會超時!如下圖所示:

為什麼之前的模擬宕機測試發現不了這一點

因為模擬宕機的時候,在事務開始的第一條SQL就會報錯,而執行SQL都是在Worker線程裏面,
所以並不會觸發reactor線程中commit超時這種現象,所以測試的時候就遺漏了這一點。

為什麼commit會變慢?

系統一直跑的好好的,為什麼突然commit就變慢了呢,而且筆者發現,這個commit變慢所關聯的DB正好也是出現慢SQL的那個DB。於是筆者立馬就去找了DBA,由於我們應用層和數據庫層都沒有commit時間的監控(因為一般都很快,很少出現慢的現象)。DBA在數據庫打的日誌裏面進行了統計,發現確實變慢了,而且變慢的時間和我們應用報錯的時間相符合!
順藤摸瓜,我們又聯繫了SA,發現其中和存儲相關的HBA卡有報錯!如下圖所示:

報錯時間都是一致的!

緊急修復方案

由於是HBA卡報錯了,屬於硬件故障,而硬件故障並不是很快就能進行修復的。所以DBA做了一次緊急的主從切換,進而避免這一問題。

一身冷汗

之前就有慢sql慢慢變多,而後突然數據庫存儲hba卡宕機導致業務不可用的情況。
而這一次到最後主從切換前為止,報錯越來越頻繁,感覺再過一段時間,HBA卡過段時間就完全不可用,重蹈之前的覆轍了!

中間件修復

我們在中間件層面將commit和rollback操作挪到Worker裏面。這樣,commit如果卡住就不再會引起創建連接失敗這種應用報錯了。

總結

由於軟件層面其實是比較信任硬件的,所以在硬件出問題時,就會產生很多詭異的現象,而且和硬件最終的原因在表面上完全產生不了關聯。只有通過抽絲剝繭,慢慢的去探尋現象的本質才會解決最終的問題。要做到高可用真的是要小心評估各種細節,才能讓系統更加健壯!

公眾號

關注筆者公眾號,獲取更多乾貨文章:

本站聲明:網站內容來源於博客園,如有侵權,請聯繫我們,我們將及時處理

【其他文章推薦】

網頁設計一頭霧水該從何著手呢? 台北網頁設計公司幫您輕鬆架站!

網頁設計公司推薦不同的風格,搶佔消費者視覺第一線

※想知道購買電動車哪裡補助最多?台中電動車補助資訊懶人包彙整

南投搬家公司費用,距離,噸數怎麼算?達人教你簡易估價知識!

※教你寫出一流的銷售文案?

※超省錢租車方案

您可能也會喜歡…