業(yè)務背景

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

問題現(xiàn)象

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

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

MQ監(jiān)控

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

分析過程

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

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

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

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

堆棧信息

圖2 堆棧信息

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

locked oracle.jdbc.driver.T4CConnection@31c02e79

T4CConnection分析

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

該連接對象對應的socket信息

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

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

T4CConnection信息

圖3 T4CConnection

Socket信息

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

獲取到Socket信息進行了如下幾個方面的分析：該Socket與Oracle服務端交互情況:

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

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

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

SQL信息

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

圖6 SQL

statements:

圖7 SQL參數(shù)值

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

解決辦法

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

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