業(yè)務(wù)背景

業(yè)務(wù)中某個(gè)應(yīng)用在消費(fèi)MQ的時(shí)候，出現(xiàn)部分機(jī)器消息堆積，隨著時(shí)間推移，堆積的機(jī)器數(shù)量越來越多，消息的堆積總量越來越多。

問題現(xiàn)象

系統(tǒng)監(jiān)控

CPU、Load、內(nèi)存、網(wǎng)絡(luò)、磁盤監(jiān)控指標(biāo)正常；JVM 內(nèi)存、GC正常。

MQ監(jiān)控

圖1 消費(fèi)者狀態(tài)

分析過程

MQ消息堆積最常見的情況是：應(yīng)用側(cè)處理MQ消息比較慢，觸發(fā)了MQ的流控機(jī)制（MQ在統(tǒng)計(jì)到應(yīng)用消費(fèi)慢的時(shí)候，會(huì)逐步減少給應(yīng)用側(cè)的消息，最糟糕的情況是MQ一條消息也不會(huì)發(fā)給應(yīng)用來消費(fèi)）。

接下來的思路是慢在了哪？

在業(yè)務(wù)監(jiān)控完備的情況下，通過分析業(yè)務(wù)監(jiān)控指標(biāo)，可以粗略定位異常點(diǎn)

明確運(yùn)行的程序在忙些什么，分析線程堆棧信息

堆棧信息

圖2 堆棧信息

上面圖片中，TID=562的線程正在read Oracle返回的信息。經(jīng)過觀測(cè)，TID=562的線程一直處于上面圖片中的狀態(tài)。由于上面圖片中的堆棧信息不完整，所以使用jstack抓取后分析出一個(gè)關(guān)鍵信息：

locked oracle.jdbc.driver.T4CConnection@31c02e79

T4CConnection分析

【oracle.jdbc.driver.T4CConnection@31c02e79】是與Oracle交互的數(shù)據(jù)庫連接對(duì)象，需要分析出

該連接對(duì)象對(duì)應(yīng)的socket信息

該連接對(duì)象正在執(zhí)行的SQL

該連接對(duì)象關(guān)聯(lián)的statements對(duì)象信息

T4CConnection信息

圖3 T4CConnection

Socket信息

圖4 與數(shù)據(jù)連接的Socket信息

獲取到Socket信息進(jìn)行了如下幾個(gè)方面的分析：該Socket與Oracle服務(wù)端交互情況:

圖5 與數(shù)據(jù)連接的TCP連接信息

//通過tcpdump分析與Oracle服務(wù)端交互的報(bào)文，發(fā)現(xiàn)該連接上沒有任何報(bào)文交互
tcpdump -i any tcp and port 45556 -A -nn

問：與Oracle DBA確認(rèn)該Socket在服務(wù)端正在執(zhí)行什么SQL？答：沒找到任何關(guān)于該Socket的信息

SQL信息

通過分析oracle.jdbc.driver.T4CConnection類代碼及【oracle.jdbc.driver.T4CConnection@31c02e79】屬性信息找到了正在執(zhí)行的SQL及與該連接關(guān)聯(lián)的statements信息：SQL:

圖6 SQL

statements:

圖7 SQL參數(shù)值

到此，我們分析出了引起線程阻塞的SQL詳情。

解決辦法

對(duì)參數(shù)是null的情況進(jìn)行過濾，不再向Oracle發(fā)送這樣的SQL語句；同時(shí)日志里對(duì)這種異常情況進(jìn)行記錄，以便更細(xì)致地分析數(shù)據(jù)為null的產(chǎn)生場(chǎng)景。

加強(qiáng)應(yīng)用可觀測(cè)性之線程執(zhí)行耗時(shí)監(jiān)控○ 在業(yè)務(wù)邏輯開始的前面，添加一個(gè)filter○ 當(dāng)請(qǐng)求到達(dá)filter的時(shí)候，將當(dāng)前線程及此時(shí)的時(shí)間記錄到一個(gè)Map中○ 當(dāng)請(qǐng)求結(jié)束回到filter的時(shí)候，將當(dāng)前線程從Map中刪除○ 單獨(dú)起一個(gè)定時(shí)任務(wù)來遍歷Map，當(dāng)發(fā)現(xiàn)Map中某個(gè)線程執(zhí)行時(shí)間超過閾值，就打印出線程的堆?！?當(dāng)開發(fā)人員收到異常堆棧的報(bào)警，人工介入進(jìn)行系統(tǒng)恢復(fù)及問題快速定位?。