原創:扣釘日記(微信公眾號ID:codelogs),歡迎分享,非公眾號轉載保留此宣告。
簡介
在之前的OOM問題覆盤之後,本週,又一Java服務出現了記憶體問題,這次問題不嚴重,只會觸發堆記憶體佔用高報警,沒有觸發OOM,但好在之前的覆盤中總結了dump指令碼,會在堆佔用高時自動執行jstack與jmap,使得我們成功保留了問題現場。
檢視堆佔用分佈
發現有heapdump檔案後,我立馬複製到本機,並使用MAT分析,如下:
很顯然,好像是什麼介面分配了非常大的String物件,一個String物件約200MB,那它是哪分配的呢?
查詢大物件分配執行緒
這個分配行為肯定是某個執行緒做的,而執行緒是最常見的GC Root,因此只要查詢物件的GC Root即可,如下:
找到了大物件對應的分配執行緒是http-nio-8088-exec-6,如下:
檢視執行緒棧
如何檢視這個執行緒在幹什麼呢?在MAT中摸索了一會,沒找到相關內容,回想起我們的dump指令碼中記錄了jstack,開啟看看,如下:
可以發現,這個執行緒正在做json序列化,但我仔細找了好一會,也沒有找到相關介面的Controller,這是因為執行緒已經執行完了Controller裡面的邏輯,之後返回介面響應資料時分配的大物件。
可是,執行緒棧中沒有業務程式碼,就沒法定位是哪個介面有問題了。。。
檢查accesslog日誌
考慮到分配大物件的介面肯定會很慢,於是我轉向檢視tomcat的accesslog日誌,如下:
終於,找到了問題介面,這個介面是用來查詢商品資料的,當輸入3時會查詢出所有3開頭的商品,而這有20w+資料,解決問題很簡單,加個limit完事。
排查過程覆盤
然而,我一直有個習慣,就是解決一個問題後,我會反思一下問題解決過程中有多少運氣成分。
如果你經常閱讀排查問題類的技術文章,就會發現不少文章,中間突然有一步定位到了問題根因,可能是突然發現了一個線索,或是硬看程式碼看出來的,或是猜測某處有問題,我覺得這種排查過程都有不少運氣成分,我希望問題是透過多年理論基礎的積累和對診斷工具的熟練使用,而有章法的一步步查出來的。
而上面透過accesslog能夠定位到問題,有一定的運氣成分,因為本次記憶體問題不極端,如果此介面請求量大,那就會瞬間觸發多次FGC,進而會影響其它介面也變慢,進而無法分辨出哪個是導致問題的介面!
我想,從理論上來說,Java堆檔案裡面,應該有執行緒棧以及執行緒棧上的引數,因為執行緒是物件,引數也是物件,它們理應都在堆裡,於是我找了個空閒時間,又摸索起MAT這個工具了。
MAT檢視執行緒棧
摸索了一會,我就發現有這樣一個按鈕,可以檢視執行緒資訊,如下:
找到前面說的執行緒http-nio-8088-exec-6,展開後,就可以發現執行緒棧以及棧上的引數,如下:
這就找到了請求的Request引數物件,再將Request物件多次展開後,就可以找到介面url資訊,如下:
嗯,這樣分析heapdump檔案真tm的高效啊?
MAT下載地址:https://www.eclipse.org/mat/downloads.php
VisualVM檢視執行緒棧
考慮到不少同學習慣用VisualVM分析heapdump,這裡也放一下VisualVM的使用方法。
首先,載入heapdump檔案,如下:
然後選擇相應物件,右鍵選擇Select in Threads,如下:
定位到執行緒棧後,找到要檢視的Request物件,點選進入,如下:
同樣,展開Request物件後,可找到url資訊,如下:
VisualVM下載地址:https://visualvm.github.io/download.html
總結
雖然我也用MAT很多次了,但每次問題都太簡單,以至於沒有深入使用過MAT,導致到現在才知道有如此便捷的分析路徑。
如果你對我們的自動dump指令碼感興趣,可看看我之前寫的這兩篇文章。
一次線上OOM問題的個人覆盤
jmap執行失敗了,怎麼獲取heapdump?