[[403694]]

前言

日常Bug排查系列都是一些簡(jiǎn)單Bug排查，筆者將在這里介紹一些排查Bug的簡(jiǎn)單技巧，同時(shí)順便積累素材^_^。

Bug現(xiàn)場(chǎng)

某天下午，在筆者研究某個(gè)問題正high的時(shí)候。開發(fā)突然找到筆者，線上某個(gè)系統(tǒng)突然消費(fèi)不了queue了。Queue不消費(fèi)也算是日常問題了。淡定的先把流量切到另一個(gè)機(jī)房，讓問題先恢復(fù)再說。

消息累積

然后就是看不消費(fèi)的queue到哪去了，打開mq(消息中間件)控制臺(tái)，全部累積到mq上了。

同時(shí)開發(fā)對(duì)筆者反映，只有這個(gè)queueu積累了，其它queue還是能正常消費(fèi)的。

出問題時(shí)間點(diǎn)

這時(shí)筆者還得到了一個(gè)關(guān)鍵信息，此問題是DBA對(duì)其關(guān)聯(lián)的數(shù)據(jù)庫進(jìn)行操作后才發(fā)生的。當(dāng)時(shí)由于操作灌入的數(shù)據(jù)庫過大，導(dǎo)致數(shù)據(jù)庫主從切換，漂了VIP。從時(shí)間點(diǎn)判斷，這個(gè)應(yīng)該是問題的誘因。

jstack

既然卡住了，那么老辦法，jstack一下，看看我們的mq消費(fèi)線程在干嘛:

ActiveMQ Session Task-1234 
    at java.net.SocketInputStream.socketRead0 
    ...... 
    at com.mysql.jdbc.MysqlIO.readFully 
    ...... 
    at org.apache.activemq.ActiveMQMessageConsumer.dispatch 
    ...... 

很明顯的，都卡在MysqlIO.readFully也就是數(shù)據(jù)庫讀取上，再也不往下走了。

沒配超時(shí)

這就肯定是沒配超時(shí)了，排查了下他們的配置，確實(shí)沒配。之前系統(tǒng)梳理過好多次，但沒想到還是有這種漏網(wǎng)之魚。這個(gè)問題分析本身是很簡(jiǎn)單的。不過在這里筆者想多聊一下，為什么數(shù)據(jù)主從切換會(huì)形成這樣的現(xiàn)象。

mha切換

如圖所示，mha切換邏輯是將vip從DB舊主上摘掉，然后將vip掛到DB新主上面。為了觀察這種行為，筆者寫了個(gè)python程序進(jìn)行測(cè)試。觀察得知，在vip被摘掉的那一刻，雙方的通信已經(jīng)不正常了。但是tcp連接狀態(tài)依舊是ESTABLISHED。

為什么tcp狀態(tài)依舊ESTABLISHED

因?yàn)閕p摘掉并不會(huì)讓已經(jīng)存在的socket立馬感知，那么socket什么時(shí)候能夠感知到我們這個(gè)連接已經(jīng)gg了呢。在當(dāng)前這個(gè)場(chǎng)景下，應(yīng)用沒設(shè)置socket超時(shí)，會(huì)有這幾種可能:

如果這時(shí)候App正在發(fā)請(qǐng)求給此五元組

如果DB正在寫回請(qǐng)求給此五元組

由上面兩種情況，我們可以知道哪方作出發(fā)送動(dòng)作，哪方就能夠通過reset或者嘗試次數(shù)過多來感知到這個(gè)連接已經(jīng)gg了。

很明顯的，由于我們的應(yīng)用正卡在socket read,表明我們的App應(yīng)用并沒有發(fā)送數(shù)據(jù)，而是在等待MySQL的返回，那么在不設(shè)置超時(shí)的情況下，App怎么感知到連接實(shí)際上已經(jīng)不好了呢。

tcp?；疃〞r(shí)器

由于應(yīng)用不做發(fā)送動(dòng)作，那這時(shí)就輪到我們的tcp?；疃〞r(shí)器tcp_keepalive出馬了。linux下默認(rèn)的內(nèi)核參數(shù)為:

/proc/sys/net/ipv4/tcp_keepalive_time 7200 兩小時(shí)

/proc/sys/net/ipv4/tcp_keepalive_probes 9 探測(cè)9次

/proc/sys/net/ipv4/tcp_keepalive_intvl 75s 每次探測(cè)間隔75s

tcp?；疃〞r(shí)器默認(rèn)在7200s也就是兩小時(shí)后開啟，探測(cè)9次，每次間隔75s，如果有明確失敗或者9次都沒返回則判定連接gg。

在我們的這個(gè)場(chǎng)景中，應(yīng)用會(huì)在兩個(gè)小時(shí)后開始?；睿诘谝淮翁綔y(cè)的時(shí)候?qū)Χ税l(fā)送reset從而應(yīng)用感知到連接gg。這時(shí)候，應(yīng)用才返回。也就是說，不設(shè)置超時(shí)時(shí)間，遇到這種情況，應(yīng)用的線程要卡2小時(shí)!

如果是DB進(jìn)程宕or重啟

如果不是mha切換，而是DB進(jìn)程重啟或者宕的話，由于Linux內(nèi)核沒宕還存在著。內(nèi)核會(huì)自動(dòng)將DB進(jìn)程所屬的socket進(jìn)行close也就是發(fā)FIN報(bào)文回去。那么應(yīng)用就可以立馬從socket read系統(tǒng)調(diào)用中返回了。

物理機(jī)宕機(jī)

物理機(jī)宕機(jī)而不漂VIP,應(yīng)用在不設(shè)置超時(shí)的時(shí)候。如果是發(fā)送數(shù)據(jù)階段，則tcp_reties2次重試后從socket read系統(tǒng)調(diào)用返回。如果不發(fā)送數(shù)據(jù)，和上面的描述基本一樣，2個(gè)小時(shí)后開啟保活定時(shí)器。唯一不同的是，這次是需要探活9次，所以需要會(huì)多花11分鐘左右的時(shí)間感知。

線下演練為什么不出問題

VIP漂移這種操作，我們?cè)诰€下演練過，當(dāng)時(shí)應(yīng)用很快就切換完了。為什么到了線上就會(huì)卡住呢?這是因?yàn)?，線下沒有加上IO hang住導(dǎo)致SQL處理時(shí)間過長(zhǎng)這一條件。SQL很快就返回了，所以我們線下的線程只有很小的概率卡在socket read上面。況且有幾十個(gè)線程在消費(fèi)，卡一兩個(gè)無關(guān)大局。

而在我們這次上面，由于SQL處理時(shí)間超長(zhǎng)，所以基本所有的線程都在VIP漂移的那一刻執(zhí)行socket read即等待數(shù)據(jù)庫返回階段，就導(dǎo)致所有線程全部hang住等。這時(shí)候只能等待tcp_keepalive或者重啟了。

本文轉(zhuǎn)載自微信公眾號(hào)「解Bug之路」，可以通過以下二維碼關(guān)注。轉(zhuǎn)載本文請(qǐng)聯(lián)系解Bug之路公眾號(hào)。