高可用性真的不能忽略細(xì)節(jié)。平時(shí)運(yùn)行良好的系統(tǒng)，如果該硬件出現(xiàn)故障，可能會(huì)引發(fā)潛在的錯(cuò)誤。

偏偏這些故障在應(yīng)用層的表現(xiàn)稀奇古怪，很難讓人聯(lián)想到是硬件出了問題，特別是偶發(fā)性出現(xiàn)的問題更難排查。今天，筆者就給大家?guī)硪粋€(gè)存儲(chǔ)偶發(fā)性故障的排查過程。

Bug現(xiàn)場

我們的積分應(yīng)用由于量非常大，所以需要進(jìn)行分庫分表，所以接入了我們的中間件。一直穩(wěn)定運(yùn)行，但應(yīng)用最近確經(jīng)常偶發(fā)連接建立不上的報(bào)錯(cuò)。報(bào)錯(cuò)如下:

GetConnectionTimeOutException

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

NIOReactor - register err java.nio.c

這樣的告警。整個(gè)Bug現(xiàn)場如下圖所示:

偶發(fā)性錯(cuò)誤

之前出過類似register err這樣的零星報(bào)警，最后原因是安全掃描，并沒有對業(yè)務(wù)造成任何影響。而這一次，類似的報(bào)錯(cuò)造成了業(yè)務(wù)的大量連接超時(shí)。由于封網(wǎng)，線上中間件和應(yīng)用已經(jīng)穩(wěn)定在線上跑了一個(gè)多月，代碼層面沒有任何改動(dòng)！突然出現(xiàn)的這個(gè)錯(cuò)誤感覺是環(huán)境出現(xiàn)了某些問題。而且由于線上的應(yīng)用和中間件都是集群，出問題時(shí)候都不是孤立的機(jī)器報(bào)錯(cuò)，沒道理所有機(jī)器都正好有問題。如下圖所示:

開始排查是否網(wǎng)絡(luò)問題

遇到這種連接超時(shí)，筆者最自然的想法當(dāng)然是網(wǎng)絡(luò)出了問題。于是找網(wǎng)工進(jìn)行排查， 在監(jiān)控里面發(fā)現(xiàn)網(wǎng)絡(luò)一直很穩(wěn)定。而且如果是網(wǎng)絡(luò)出現(xiàn)問題，同一網(wǎng)段的應(yīng)用應(yīng)該也都會(huì)報(bào)錯(cuò) 才對。事實(shí)上只有對應(yīng)的應(yīng)用和中間件才報(bào)錯(cuò)，其它的應(yīng)用依舊穩(wěn)穩(wěn)當(dāng)當(dāng)。

又發(fā)生了兩次

就在筆者覺得這個(gè)偶發(fā)性問題可能不會(huì)再出現(xiàn)的時(shí)候，又開始抖了。而且是一個(gè)下午連抖了兩次。臉被打的啪啪的，算了算了，先重啟吧。重啟中間件后，以為能消停一會(huì)，沒想到半個(gè)小時(shí)之內(nèi)又報(bào)了?？磥斫裉觳桓傻暨@個(gè)Bug是下不了班了!

開始排查日志

事實(shí)上，筆者一開始就發(fā)現(xiàn)中間件有調(diào)用后端數(shù)據(jù)庫慢SQL的現(xiàn)象，由于比較偶發(fā)，所以將這個(gè)現(xiàn)象發(fā)給DBA之后就沒有繼續(xù)跟進(jìn),DBA也反饋SQL執(zhí)行沒有任何異常。筆者開始認(rèn)真分析日志之后，發(fā)現(xiàn)一旦有 中間件的register err 必定會(huì)出現(xiàn)中間件調(diào)用后端數(shù)據(jù)庫的sql read timeout的報(bào)錯(cuò)。但這兩個(gè)報(bào)錯(cuò)完全不是在一個(gè)線程里面的，一個(gè)是處理前端的Reactor線程，一個(gè)是處理后端SQL的Worker線程，如下圖所示:

這兩個(gè)線程是互相獨(dú)立的，代碼中并沒有發(fā)現(xiàn)任何機(jī)制能讓這兩個(gè)線程互相影響。難道真是這些機(jī)器本身網(wǎng)絡(luò)出了問題？前端APP失敗，后端調(diào)用DB超時(shí)，怎么看都像網(wǎng)絡(luò)的問題！

進(jìn)一步進(jìn)行排查

既然有DB(數(shù)據(jù)庫)超時(shí)，筆者就先看看調(diào)用哪個(gè)DB超時(shí)吧，畢竟后面有一堆DB。筆者突然發(fā)現(xiàn)，和之前的慢SQL一樣，都是調(diào)用第二個(gè)數(shù)據(jù)庫超時(shí)，而DBA那邊卻說SQL執(zhí)行沒有任何異常，

筆者感覺明顯SQL執(zhí)行有問題，只不過DBA是采樣而且將采樣耗時(shí)平均的，偶爾的幾筆耗時(shí)并不會(huì)在整體SQL的耗時(shí)里面有所體現(xiàn)。

只能靠日志分析了

既然找不到什么頭緒，那么只能從日志入手，好好分析推理了。REACTOR線程和Worker線程同時(shí)報(bào)錯(cuò)，但兩者并無特殊的關(guān)聯(lián)，說明可能是同一個(gè)原因引起的兩種不同現(xiàn)象。筆者在線上報(bào)錯(cuò)日志里面進(jìn)行細(xì)細(xì)搜索，發(fā)現(xiàn)在大量的

NIOReactor-1-RW register err java.nio.c

日志中會(huì)摻雜著這個(gè)報(bào)錯(cuò):

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

這一看就發(fā)現(xiàn)了端倪，Reactor作為一個(gè)IO線程，怎么會(huì)有數(shù)據(jù)庫調(diào)用呢?于是翻了翻源碼，原來，我們的中間件在處理commit/rollback這樣的操作時(shí)候還是在Reactor線程進(jìn)行的！很明顯Reactor線程卡主是由于commit慢了!筆者立馬反應(yīng)過來,而這個(gè)commit慢也正是導(dǎo)致了regsiter err以及客戶端無法創(chuàng)建連接的元兇。如下面所示:

由于app1的commit特別慢而卡住了reactor1線程，從而落在reactor1線程上的握手操作都會(huì)超時(shí)！如下圖所示:

為什么之前的模擬宕機(jī)測試發(fā)現(xiàn)不了這一點(diǎn)

因?yàn)槟M宕機(jī)的時(shí)候，在事務(wù)開始的第一條SQL就會(huì)報(bào)錯(cuò)，而執(zhí)行SQL都是在Worker線程里面， 所以并不會(huì)觸發(fā)reactor線程中commit超時(shí)這種現(xiàn)象，所以測試的時(shí)候就遺漏了這一點(diǎn)。

為什么commit會(huì)變慢?

系統(tǒng)一直跑的好好的，為什么突然commit就變慢了呢，而且筆者發(fā)現(xiàn)，這個(gè)commit變慢所關(guān)聯(lián)的DB正好也是出現(xiàn)慢SQL的那個(gè)DB。于是筆者立馬就去找了DBA,由于我們應(yīng)用層和數(shù)據(jù)庫層都沒有commit時(shí)間的監(jiān)控(因?yàn)橐话愣己芸?，很少出現(xiàn)慢的現(xiàn)象)。DBA在數(shù)據(jù)庫打的日志里面進(jìn)行了統(tǒng)計(jì)，發(fā)現(xiàn)確實(shí)變慢了，而且變慢的時(shí)間和我們應(yīng)用報(bào)錯(cuò)的時(shí)間相符合！ 順藤摸瓜，我們又聯(lián)系了SA，發(fā)現(xiàn)其中和存儲(chǔ)相關(guān)的HBA卡有報(bào)錯(cuò)！如下圖所示:

報(bào)錯(cuò)時(shí)間都是一致的！

緊急修復(fù)方案

由于是HBA卡報(bào)錯(cuò)了，屬于硬件故障，而硬件故障并不是很快就能進(jìn)行修復(fù)的。所以DBA做了一次緊急的主從切換，進(jìn)而避免這一問題。

一身冷汗

之前就有慢sql慢慢變多，而后突然數(shù)據(jù)庫存儲(chǔ)hba卡宕機(jī)導(dǎo)致業(yè)務(wù)不可用的情況。 而這一次到最后主從切換前為止，報(bào)錯(cuò)越來越頻繁，感覺再過一段時(shí)間,HBA卡過段時(shí)間就完全不可用，重蹈之前的覆轍了！

中間件修復(fù)

我們在中間件層面將commit和rollback操作挪到Worker里面。這樣，commit如果卡住就不再會(huì)引起創(chuàng)建連接失敗這種應(yīng)用報(bào)錯(cuò)了。

總結(jié)

由于軟件層面其實(shí)是比較信任硬件的，所以在硬件出問題時(shí)，就會(huì)產(chǎn)生很多詭異的現(xiàn)象，而且和硬件最終的原因在表面上完全產(chǎn)生不了關(guān)聯(lián)。只有通過抽絲剝繭，慢慢的去探尋現(xiàn)象的本質(zhì)才會(huì)解決最終的問題。要做到高可用真的是要小心評(píng)估各種細(xì)節(jié)，才能讓系統(tǒng)更加健壯！

作者：無毀的湖光-Al

原文：