2014年2月15日土曜日

javaのOutOfMemory時のヒープの分析にチャレンジ(MemoryAnalyzer)

前回でjhatを使ってOOM時のヒープ分析を試みたが、時間がかかってしょうがないので、断念。次にEclipseのMemoryAnalyzerを使ってみる。

1.MemoryAnalyzer(MAT)のインストール

 MATには、EclipseのPlug-inと、Standalone版があるらしいので、今回はStandaloneで試す。
 Versionは現時点(2014/2/15)で1.3.1だった。

http://www.eclipse.org/downloads/download.php?file=/mat/1.3.1/rcp/MemoryAnalyzer-1.3.1.20140107-win32.win32.x86_64.zip

 これを解凍して、適当なフォルダにコピーすれば完了らしい(Javaは1.5以上が必要)。

2.起動しMATにhprofデータを読み込ませる

 上記コピーしたフォルダのMemoryAnalyzer.exeを起動すると画面が出てくる。
 ここからダンプファイルを開いて、「Leak Suspects Report」を選択すると、以下のような画面が出てくる。

 うーん、jhatと比べて圧倒的に速いです。
 上記画面から「Dominator tree」を選択すると、classとヒープ消費(Retained Heap)の一覧がでてくるので、「Retained Heap」順にソートして、消費量の大きなClassをたどると、大きなものがあるのか?小さなものが沢山あるのか?がわかる。
 ただし、これがメモリリークなのかただ負荷がかかったのか?はOOM前のヒープダンプを取得して、比較しながら進める必要がある。その場合は、Javaのオプションも追加して対応が必要。

 これでおおよそ、OOMが出た原因は判明する。このレベルであれば楽ちんでしたね。

javaのOutOfMemory時のヒープの分析にチャレンジ(jhat)

javaアプリでOUtOfMemoryが出ているので、ちょっとヒープの中身を見てみた。

環境は以下の通り

 ・OOMの出た環境
  OS:CentOS 6.4(64bit)
  tomcat:6.0.35
  Java:1.6.0_30

 ・解析につかったPC(自作PC)
  OS:Windows8.1
  CPU:3.2GHz 1P4C
  MEMORY:16GB
  Tool:Java1.7標準でついてくるjhatとEclipseのMemoryAnalyzer

まずはjhatで試してみた。

1.解析対象となるヒープのダンプデータをゲット

 hprofによるheapdumpの取得をする。今回は事前に仕込んでいたが、Javaの起動引数で

  -XX:+HeapDumpOnOutOfMemoryError

 をつけると、OOMが出たときに、java_pid[xxxx.]hprofというヒープのダンプが出力される。
 別途の監視システムでOutOfMemoryが出たら自動再起動という仕組みを入れている場合は、
 出力仕切る前にサービス再起動されてしまうので、要注意。

 今回ヒープが大きかった(Heap 2GB/Perm 512MB)からか、hprofのサイズが3GBにもなった。

 ※参考
   http://docs.oracle.com/javase/jp/7/technotes/samples/hprof.html

2.jhatにかましてみる

 上記でゲットしたhprofファイルをjhatで開いてみる。

 #jhat  java_pid24328.hprof

 結構いいPCを使っているなのだが、CPUが張り付いた。でもっていつまでたっても終わらない。
 プロセスを見るとメモリが(PrivateWorkingSet)が3GB付近で止まっている。何か怪しい・・
 ということで、オプションをつけて再度確認

 #jhat  -J-verbose:gc java_pid24328.hprof
 
 GCが結構な頻度で実行されている。

 #jhat  -J-verbose:gc -J-mx6000m -J-ms6000m java_pid24328.hprof

 で再実行。さっきよりはもちろん頻度は落ちたが、まだFullGCが出る(そしてFullGC 1回に15秒くらいかかっている)。だんだんFullGCの頻度が上がってきた。。まだ足りないか・・
 
 #jhat  -J-verbose:gc -J-mx10000m -J-ms10000m java_pid24328.hprof

 Dump file created Wed Feb 12 19:45:24 JST 2014
 [GC 2560512K->2161709K(9814016K), 1.7790619 secs]
 [GC 4722221K->4292917K(9814016K), 2.2919729 secs]
 [GC 6853429K->6801901K(9814016K), 2.9861100 secs]
 [Full GC 6801901K->6401515K(9814016K), 27.1854356 secs]
 Snapshot read, resolving...
 Resolving 56763698 objects...
 [Full GC 8962027K->6641624K(9814016K), 29.9023006 secs]
 [Full GC 9202136K->6313543K(9814016K), 27.5518345 secs]
 Chasing references, expect 11352 dots................................
 ........................................................................................................................
 (ドットが11352個出たのかな)
 ........................................................................................................................
 Snapshot resolved.
 Started HTTP server on port 7000
 Server is ready.

で完了した。結構時間かかった。こんなのサーバ上でやれないですね(hprofの出力を絞ればいいのかな)。

3.結果をみる

 ブラウザで、http://127.0.0.1:7000/ で見てみる。

 これだとよくわからないなぁとおもったので、最後のほうにある「Show heap histogram」をクリックしてみたら、、これまたレスポンスが返ってこない。。(GCが出ているわけでもない)。
10分たってもレスポンスが返ってこないので、、諦めました。やはりでかすぎたのかな。ということで、次回MemoryAnalyzerに期待。