業務背景

業務中某個應用在消費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中某個執行緒執行時間超過閾值，就打印出執行緒的堆疊

○ 當開發人員收到異常堆疊的報警，人工介入進行系統恢復及問題快速定位