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

時間 2020-10-15

標籤前端 java react sql 數據庫後端安全網絡 app 測試欄目 Java 简体版

原文原文鏈接

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

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

Bug現場

咱們的積分應用因爲量很是大，因此須要進行分庫分表，因此接入了咱們的中間件。一直穩定運行，但應用最近確常常偶發鏈接創建不上的報錯。報錯以下:java

GetConnectionTimeOutException

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

NIOReactor - register err java.nio.channels.CloasedChannelException

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

偶發性錯誤

以前出過相似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的耗時裏面有所體現。
app

只能靠日誌分析了

既然找不到什麼頭緒，那麼只能從日誌入手，好好分析推理了。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卡有報錯！以下圖所示:

報錯時間都是一致的！