簡介
在之前的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?