【轉】又一次線上 OOM 排查通過

又一次線上OOM排查通過

 

最近線上一個服務又出現了頻繁Full GC的狀況，致使提供的業務常常超時。問題出現很是不穩定，通過兩週的時候，終於又捕捉到了一次Full GC，因而聯繫運維作Heap Dump以後，通過一系列分析，終於解決問題。此次的問題稍微複雜一點，可是也比較有表明性，用到了VisualVM和MAT兩個工具，繼續記錄以下。

現象

此次使用公司的CAT監控平臺看到的內存表現以下：

能夠看到，具體表現是：

1. 在很長一段時間內(數個小時)，New GC比較頻繁，Full GC較少(一小時個位數)。
2. 過了某一時間點後，Full GC增長，New GC則減小。
3. 將服務切換下線後，Memory Free逐漸回升，Full GC減小。

而後觀察某一時刻的JMAP histo的內容以下：

num     #instances         #bytes  class name ---------------------------------------------- 1: 5958517 5840833584 [C 2: 37983 706246056 [B 3: 5960539 190737248 java.lang.String 4: 1522282 126603936 [Ljava.lang.Object; 5: 3692000 88608000 java.lang.Double 

能夠看到"[C"即"char[]"佔用內存達到了5.8G，它正是String的內部結構，換句話說，由於存在了大量的大String致使這個問題。

聯繫運維進行了Heap Dump以後，就開始了分析的過程。由於服務器內存有8G，因此相應的DUMP也有8G，對分析也形成了一點小困難。

下面是一些工具的使用過程，操做系統是OS X 10.8。

使用VisualVM分析

首先使用VisualVM對Heap Dump進行分析。分析須要比較大的內存，而VisualVM默認的內存是256M，因此須要先設置/Applications/VisualVM.app/Contents/Resources/visualvm/etc/visualvm.conf中的最大內存量，這裏咱們設置成了4G-J-Xmx4096m。

好了，如今打開dump文件，整個分析過程共佔用內存2G，仍然在可接受範圍。以後分析內存，能夠看到跟以前histo同樣的類關係。

不一樣的是，這時候能夠點進去，查看具體的對象。這裏看到，居然有幾個大的String佔用了756M的內存，看來咱們找到問題了。

發現一個奇怪的現象：「計算保留大小」以後，這些String的保留大小都是0。

保留大小是什麼呢？

它是分析工具從GC roots開始查找，找到的全部不會回收的對象，而後按照引用關係，計算出這個「對象以及它引用的對象」的內存大小。這裏頗有趣的是，這些對象的保留大小都是0。

開始我甚至覺得是工具出了問題，後來想一想，其實答案很簡單：這些大String是臨時對象，沒有什麼對象持有它——經過分析這些String的依賴關係也說明了這一點。這些對象是能夠被回收的，換句話說，並非有明顯的內存泄露。

這個「沒有對象持有的String」頗有意思，讓我想到了，會不會是log的過程當中，產生了這個String？由於log的時候，會調用對象的toString()方法，而一個大對象的toString()多是很大的。查看了一下String的內容，是[Class[field1=xxx,field2=yyy]]這種結構，幾乎能夠確定是toString()的結果，那麼咱們如今只要查看一下具體的內容，究竟是哪裏太大就能夠了。

惋惜的是，VisualVM裏我嘗試了各類方法，都沒有辦法Dump出這個對象的數據，甚至還嘗試了VisualVM提供的OQL。

OQL是一種類SQL的表達式，同時整合了一些Javascript的函數功能，可是它的缺點就是太慢了…最後嘗試用OQL Dump對象未果。

使用MAT分析

轉而嘗試一下MAT。Eclipse MAT(Memory Analyzer Tool)是一個強大的內存分析工具，它能夠方便的分析內存泄露的問題。實際使用以後，確實也感受到比VisualVM更增強大一些。

咱們使用MAT打開Dump文件，這也是一個漫長的過程。與VisualVM不一樣的是，MAT分析的時候，會在本地產生幾個臨時文件保存分析結果，因此相應的內存佔用會小一些(1G左右)，第二次打開也會快不少。

打開完成後，咱們看到能夠看到幾個佔用內存較大的對象，這就是最可疑的內存泄漏源。意外的是Size顯示的只有1.3GB，並且咱們的大String都沒在裏面。

開始咱們一度認爲是Dump文件有錯，後來上網搜索才知道，由於MAT的主要目標是排查內存佔用量，因此默認大小是不計算不可達對象的——而咱們的String都是不可達對象。對應Eclipse的文檔裏有介紹http://wiki.eclipse.org/MemoryAnalyzer/FAQ#How_to_analyse_unreachable_objects。

因而咱們按照說明，在"Preferences=>Memory Analyzer"中勾選"Keep Unreachable Objects"，刪除索引文件Dump同路徑下的全部".index"，便可看到全部的對象。

點擊Histogram，便可看到類的佔用。在類上選擇"List Objects"，便可看到全部對象。在對象上選擇"Copy=>Value to File"，便可保存到文件。

原理

以後咱們經過分析對象，發現是由於某個用於緩存的對象使用了一個List結構，可是添加元素的沒有去重，致使List愈來愈大形成的。這個對象自己佔用內存只有110M，可是toString()出來的字符串達到700M的大小，因此引發了頻繁的GC——最開始對象小的時候是New GC，後來對象大了，直接進入了年老代，就變成了Full GC。

總結

回到以前的問題，經過此次分析，咱們能夠這麼總結：

1. 將服務切換下線後，Memory Free逐漸回升，Full GC減小，Heap Dump的可達對象較少

   這種狀況不是內存泄露，有多是對象建立開銷太大形成的。

2. 在1的前提下，New GC很頻繁

   這種狀況多是頻繁建立小對象，或者建立一些較大的對象(尚不足以直接進入年老代)

3. 在1的前提下，Full GC很頻繁

   這種狀況是頻繁建立大對象，或者建立了一些超大對象致使的。

4. 第3種狀況下，大對象toString()產生的大String極可能是罪魁禍首