解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如果卡住就不再會引起創建連接失敗這種應用報錯了。

總結

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

公眾號

關注筆者公眾號，獲取更多干貨文章: