解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如果卡住就不再會引起建立連線失敗這種應用報錯了。
總結
由於軟體層面其實是比較信任硬體的，所以在硬體出問題時，就會產生很多詭異的現象，而且和硬體最終的原因在表面上完全產生不了關聯。只有通過抽絲剝繭，慢慢的去探尋現象的本質才會解決最終的問題。要做到高可用真的是要小心評估各種細節，才能讓系統更加健壯！
公眾號
關注筆者公眾號，獲取更多幹貨文章:
