業務背景

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

問題現象

系統監控

CPU、Load、內存、網絡、磁盤監控指標正常；JVM 內存、GC正常。

MQ監控

圖1 消費者狀態

分析過程

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

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

在業務監控完備的情況下，通過分析業務監控指標，可以粗略定位異常點

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

堆棧信息

圖2 堆棧信息

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

locked oracle.jdbc.driver.T4CConnection@31c02e79

T4CConnection分析

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

該連接對象對應的socket信息

該連接對象正在執行的SQL

該連接對象關聯的statements對象信息

T4CConnection信息

圖3 T4CConnection

Socket信息

圖4 與數據連接的Socket信息

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

圖5 與數據連接的TCP連接信息

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

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

SQL信息

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

圖6 SQL

statements:

圖7 SQL參數值

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

解決辦法

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

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