本文以我司生產環境Java應用內存泄露爲案例進行分析,講解如何使用Eclipse的MAT分析定位問題html
一. 背景
11月10號晚上8點收到報警郵件,一看是OOM前端
打開公司監控系統查看應用各項指標發現JVM中老年代在持續增加(從上次發佈10月30號到11月10號的12天內一直在增加, 存在內存泄露跡象)
從圖中能夠看出, 從10月30號發佈到11月10號oom期間11天老年代一直在緩慢上漲, 雖然有降低, 但總體趨勢是上升的,平均天天泄露約50M內存, 說明每次都沒法徹底釋放乾淨java
由於生產環境的JVM添加了-XX:+HeapDumpOnOutOfMemoryError
參數,該配置會把dump文件的快照保存下來供後續分析排查問題,也可使用jmap或jcmd等jvm命令進行dump:git
jmap -dump:format=b,file=文件名 [pid] jcmd pid GC.heap_dump 文件路徑
二. 分析內存泄露
內存泄露和內存溢出的區別:內存泄露從老年代的增加狀況看是緩慢上升的, 最終達到老年代上限纔會致使溢出,有些內存泄露可能須要很長的時間發生, 因此說內存泄露更隱蔽, 不像內存溢出那樣容易暴露(內存溢出直接拋出OOM), 並且內存長時間得不到釋放會致使服務性能愈來愈差、gc時間變長、響應變慢:
從圖中能夠看出在12天裏天天大概泄露(增加)50m左右, 這種狀況下定位泄露緣由須要屢次dump採集樣本, 而後和上次的比較分析, 即須要多個dump文件進行比較分析才能精肯定位問題。 不然很難看出具體泄露的點, 加上dump文件中大部分是正常的內存使用, 會干擾問題的定位, 增長排查難度。web
因此當時的作法是天天固定時間dump一次, 採集足夠多的樣本, 以下圖:
另外測試環境很差重現的主要緣由是不清楚是哪一個接口調用引發的, 這個Java服務有多個暴露的api, 並且測試環境不方便壓測,壓測量大了, 底層接口熔斷, 壓測量小看不出泄露跡象, 因此得從dump分析入手, 找到問題所在再去測試環境驗證。apache
這裏使用Eclipse的memory analysis tool(MAT)工具進行分析json
把下載到本地的多個dump文件用mat依次打開(「File → Open Heap Dump」), 以下圖:
好比咱們要分析這3個dump文件(固然你也能夠分析更多個, 這樣會更精準), 打開後, 使用compare basket功能找出內存泄露的差別點:api
1. 使用 Compare Basket 功能分析內存泄露
1> 菜單欄 window → compare basket ,打開比較窗口(若是最下面一欄已經有compare basket則這步不須要),以下圖:
2> 依次打開3個dump的dashboard面板, 在下方的 Actions一欄點擊"histogram"或"dominator tree"生成對應的直方圖或支配樹列表,以下圖:
直方圖或支配樹均可以列出堆中存活的全部對象,但兩者的維度不一樣, 直方圖按照類型統計, 支配樹是以對象維度統計。數組
若是你對項目代碼比較熟悉, 經過直方圖定位內存泄露會更快,由於它是按照類型所有平鋪開的,若是這個項目不是你負責的, 建議使用支配樹的方式, 由於支配樹包含了對象之間的引用關係(支配樹視圖能夠展開查看內部引用層級)緩存
3> 咱們以支配樹作比對, 在最下面一欄的"Navigation History (window → navigation history)"裏(直方圖相似)找到在第2步打開的支配樹dominator tree圖標, 右鍵添加到compare basket, 以下圖:
4> 重複上面的2, 3步驟依次把其餘的dump文件添加到"compare basket"欄, 而後點擊右上角的紅色感嘆號, 生成比較結果,以下圖:
(注意比較的dump文件的順序,時間最先的在上面,能夠經過右上角的上箭頭↑和下箭頭↓調整順序)
生成的比對結果以下:
Shallow Heap一列後面的序號 #0, #1, #2 分別對應:
第一個dump文件佔用的shallow size, 第二個dump文件佔用的shallow size , 第三個dump文件佔用的shallow size
Retained Heap #0, Retained Heap #1, Retained Heap #2 這3列分別對應:
第一個dump文件佔用的retained size, 第二個dump文件佔用的retained size , 第三個dump文件佔用的retained size
紅框 圈出的是內存連續增加的對象, 能夠經過右邊紅框的retained heap看出內存變大的趨勢
綠框 圈出的是沒有變化的對象(至少在這3次比較中沒有變化),
藍框 圈出的是內存佔用降低的對象
通常咱們主要關注紅框標出的對象, 由於這部分發生內存泄露的嫌疑最大
這裏先區分兩個概念:
Shallow Size
- 對象自身佔用的內存大小,不包括它引用的對象。
- 針對非數組類型的對象,它的大小就是對象與它全部的成員變量大小的總和。
- 針對數組類型的對象,它的大小是數組元素對象的大小總和。
Retained Size
- Retained Size=當前對象大小+當前對象可直接或間接引用到的對象的大小總和。(間接引用的含義:A->B->C, C就是間接引用)
- Retained Size就是當前對象被GC後,從Heap上總共能釋放掉的內存。
由於這裏咱們比較的是支配樹, 因此按照retained heap倒序排列, 從左到右依次爲: retained heap #0 → retained heap #1 → retained heap #2(以最後一個retained heap #2 倒序, 由於這個是最後一次dump的內存快照, 這樣能夠看出內存泄露的增加趨勢)
2. 定位內存泄露
基於上一步得出的比較結果, 能夠看出"org.apache.tomcat.util.threads.TaskThread http-nio-8080-exec-*
" 有內存泄露的嫌疑, 查看它的引用關係:
點擊"with outgoing references"後逐層展開第一個對象內部的引用關係(以Retained Heap倒序,主要是看retained size排在前面的對象), 以下:
能夠看到TaskThead
內部有一個threadLocal
, threadLocal
內部有一個concurrentHashMap
, 這個map裏存的是咱們的日誌相關對象"com.*.framework.log.FieldAppendedValue
",從下面幾個map裏的key能夠肯定是咱們記錄到日誌系統(ElasticSearch)的對象, 這些日誌對象主要記錄調用接口的請求報文、響應報文、SOA接口名稱等信息,以下圖:
但爲何日誌對象會佔用這麼多內存?並且這裏看到的只是其中一個taskThread裏,繼續展開RESPONSE_CONTENT的val對象FieldAppendedValue
內部引用, 以下:
發現FieldAppendedValue
內部維護了一個CopyOnWriteArrayList
對象, 這個list里居然存放了10674個值,正常來說不可能一次接口請求會有這麼多的日誌對象, 並且接口請求完記錄到ES後, 這部份內存就應該釋放了纔對。
查看CopyOnWriteArrayList
內部存儲的內容,以下:
隨便打開10675箇中的幾個FieldAppendedValue
, 發現內部存放的都是同一個接口的請求響應報文,以下圖:
能夠右鍵copy→ value 把值複製出來查看, 接口報文以下:(響應報文)
{ "ResponseStatus": { "Timestamp": "/Date(1605583909438+0800)/", "Ack": "Success", "Errors": [], "Build": null, "Version": null, "Extension": [] }, "downloadUrl": "https://ii066.cn/hFGBEW" }
從上面那張concurrentHashMap
截圖(key : SOA_METHOD_NAME) 可知這個接口名是: getDownloadLink, 也就是說list裏10675個日誌對象存的都是"getDownloadLink"這個接口的報文。並且這只是其中一個TaskThead內部狀況, 加上所有20個對象, 20 * 10675 大概是213500個接口報文,以下圖:
這個接口是什麼鬼?
3. 代碼分析
查看代碼得知這個接口並沒什麼幺蛾子,只是當時的開發同窗在調用這個底層接口時新接入了咱們部門封裝的SOA組件公共類:AbstractSimpleHandler.java
(這個公共類主要是經過模板方法在調用接口時記錄報文日誌埋點、超時時間設置、mock等功能)
此次出現OOM的這個Java項目以前調用soa接口是本身實現了一套公共方法(早於框架以前實現), 也就是說只有這一個接口使用了新的公共類AbstractSimpleHandler
,其餘的接口調用方式仍是原來的方式。
新的工具類AbstractSimpleHandler
記錄接口報文的代碼是經過調用ELKLogUtils.write()
實現的, 這個方法的內部大體邏輯以下:
Object value = HttpContext.get(BEHAVIOR_LOG); if (value == null) { value = new ConcurrentHashMap<>(); HttpContext.add(BEHAVIOR_LOG, value); }
HttpContext內部維護的是一個ThreadLocal:
public class HttpContext { private static final int CONTEXT_DEFAULT_SIZE = 1 << 6; private static final ThreadLocal<Map<String, Object>> CONTEXT = new ThreadLocal<Map<String, Object>>() { @Override protected Map<String, Object> initialValue() { return new ConcurrentHashMap<>(CONTEXT_DEFAULT_SIZE); } };
全部調用soa底層接口的報文日誌都是經過ThreadLocal
內的map存儲的, 而後統一發送到ES日誌系統。
咱們都知道theadLocal
是線程安全的, 可是通常咱們的項目都是部署在Tomcat等web容器裏, tomcat維護了一個http線程池, 就是前面截圖的那個TaskThead Http-nio*
線程對象,每次前端app發起請求都會從tomcat的線程池裏取一個線程處理前端的請求, 若是複用的是上一個線程, 那他內部的threadLocal
沒有清空, 仍是會保存上次的報文信息,這樣的話此次請求又會繼續存放接口報文, 就會越積越多。。。
新接入的組件把接口報文存到threadLoacl
的代碼是在AbstractSimpleHandler.java
裏的,而清除threadLoacl
的代碼是在另一個公共類BaseService.java
裏作的,也就是說要接入新的公共類除了AbstractSimpleHandler.java
外,還要接入BaseService.java
這個公共類!
這個也是有歷史緣由的, 這個Java項目自己比較早, 那時候尚未咱們部門框架的SOA公共類, 因此本身實現了一套,後來使用新的框架組件調用接口的開發小夥伴沒有調研全面, 少接了一個公共類(BaseService
)致使了這一問題發生。
因此這個問題的根因是threadllocal使用不當引發的內存泄露
弄清楚緣由後就好辦了, 解決辦法是在請求完接口後主動調用下框架裏的HttpContext.clear()
, 清除下框架內部的threadlocal.map
便可,固然後續仍是要統一接口的調用方式, 不能兩套工具類並存。
4. 使用 Path To Gc Root 定位業務代碼
還有另一個內存泄露的嫌疑是"com.*.common.utils.ITextRendererPoolManager
", 如上面比對結果的圖:
單獨在dominator tree支配樹視圖展開如圖所示:
ITextRendererPoolManager
內部使用了apache的一個對象緩衝池, 目的多是爲了對象複用, 繼續展開,以下圖:
發現是pdf的一個工具類:org.xhtmlrenderer.pdf.ITextRenderer
, 這個開源的pdf工具是咱們項目的郵件功能在發送附件的時候生成pdf文檔時引入的一個第三方jar包,開始懷疑是不是這個開源的pdf工具致使的內存泄露, 可是不清楚這個jar包是在哪裏調用的?
這裏能夠經過"path to gc root"查看是誰在引用他, 即咱們業務代碼調用的地方,以下圖:
這裏先說下"path to gc root"選項的含義:
- with all references : 全部引用, 包括強引用, 弱引用, 軟引用, 虛引用
- exclude weak reference : 排除弱引用
- exclude soft reference : 排除軟引用
- 。。。。
咱們知道軟引用, 弱引用這些在發生full gc時可能會被回收掉(回收時機不一樣, 具體可自行百度), 目的是不形成內存溢出。 通常引發內存溢出的都是強引用,因此你能夠選擇"exclude all ptantom/weak/soft reference"只查看強引用。
但在這個案例中pdf.ITextRenderer是被軟引用引用的(從上圖中能夠看出), 雖說軟引用不會致使溢出, 但可能會引發內存一點點上升(軟引用只有在內存不足發生GC時纔會被回收), 這個跟本地緩存還不同, 由於shareContext對象沒有達到複用的目的, 並且最重要的是它沒有失效機制,只要沒有達到堆最大值或發生full gc就會一直存在, 這樣的話會拖累JVM的性能,因此我選擇"with all references"查看全部類型引用:
發現是被PdfUtil
這個類引用, 查看代碼發現PdfUtil
是咱們本身封裝的一個pdf工具類, 這個工具類把建立pdf的ITextRenderer
對象緩存到了iTextRendererPoolManager
對象池裏, 這樣下次就不須要再從新建立, 代碼大體以下:
try (ByteArrayOutputStream outputStream = new ByteArrayOutputStream()) { iTextRenderer = iTextRendererPoolManager.borrowObject(); ...... iTextRenderer.layout(); } catch (Exception e) { LOGGER.error(e); } finally { if (iTextRenderer != null) { iTextRendererPoolManager.returnObject(iTextRenderer); } }
可是在放回對象池前沒有對ITextRenderer
裏面的sharedContext
屬性清空, 這樣的話下次從對象池裏若是仍是獲取到這個對象,就會對ITextRenderer
內部的屬性sharedContext
繼續疊加。。。
查了下官方使用手冊發現沒有這樣的用法, 因此致使這個問題的緣由應該是咱們使用的姿式不對
解決方法一種是繼續使用對象池,但在放回對象池以前先清除下SharedContext
, 或者簡單點再也不用對象池,每次new一個, 由於是在方法內部建立的局部變量, 不會逃逸出方法外, 方法調用完就自動釋放了。
三. 驗證結果
修復上述兩個問題後在測試環境驗證經過而後發佈上線從12月10號一直截止到今天,大概18天裏內存再沒有泄露跡象, 堆外內存(RSS-JVM內存)也穩定下來,以下圖:
至此, 內存泄露問題算是告一段落。
四. 總結
查看git提交記錄發現這個問題在線上存在有一段時間了(10月30號以前就有泄露跡象),以前一直沒報出來主要是每週都有發版,發佈確定會重啓清空內存,發佈頻繁也就掩蓋了這個問題,因此這個問題實際上是一直存在的
但測試環境又很難重現出來,不多有應用在測試環境壓測10天以上的,壓測頻率高了,接口容易熔斷。。。
並且有些泄露也不是"真正的泄露", 好比本地緩存的失效策略設置不合理、寫多讀少、內存佔用持續上升,直到觸發拋棄策略等。
其實下面的三種狀況都屬於廣義上的內存泄露:
- 仍然具備GC ROOT根引用但從未在應用程序代碼中使用的對象。這也是傳統意義上的內存泄漏
- 對象太多或太大。意味着沒有足夠的堆可用於執行應用程序,由於內存中保存了太大的對象樹(例如緩存)
- 臨時對象太多。意味着Java代碼中的處理暫時須要太多內存
第一種是你們都熟悉的內存泄露,後兩種多半屬於寫代碼不規範,或業務流程上設計不合理或寫代碼時沒充分考慮緩存的使用場景,因此:
- 寫代碼時要增強這方面的意識,包括review的人
- 發佈上線後要定時監控,及早發現這類問題
五. MAT工具使用相關事項
使用mat前最好把初始化內存設置大一點,由於通常生產環境的dump文件都比較大,mat內存大小至少要cover住dump文件的大小,不然打開會報錯,配置文件如圖:
好比下面堆內存的最大(Xmx)最小(Xms)設置爲4G(具體以你dump文件大小爲準):
-startup plugins/org.eclipse.equinox.launcher_1.3.100.v20150511-1540.jar --launcher.library plugins/org.eclipse.equinox.launcher.win32.win32.x86_64_1.1.300.v20150602-1417 -vmargs -Xms4g -Xmx4g
另外最好設置下顯示單位, 以兆 M/G 爲單位更便於理解,如圖: