歡迎光臨
每天分享高質量文章

又一次線上 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技能

赞(0)

分享創造快樂