又一次線上 OOM 排查經過

（點選上方公眾號，可快速關註）

來源：黃億華 ，

my.oschina.net/flashsword/blog/265442

最近線上一個服務又出現了頻繁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很可能是罪魁禍首。

看完本文有收穫？請轉發分享給更多人

關註「ImportNew」，提升Java技能