TomcatでFullGC多発の原因調査

Tumblrからの移行記事2

Tomcatで動かしてるアプリケーションに負荷をかけるとFullGCが発生し、それ以降はFullGCが多発する現象が発生しました。
ここではその際の調査に使用した方法を簡単にまとめておきます。
ちなみにTomcatはWindows環境でEclipseから実行してます。

1.ヒープ統計情報の確認

Tomcatの起動オプションに

-verbose:gc(-Xloggc:path_to_file)
-XX:+PrintClassHistogram

を追加。
その後Unix環境なら

kill -3 <pid>

でcatalina.outに統計情報が出力され、 Windows(Unixも)では

%JAVA_HOME%/bin/jmap -histo <pid>

でコンソールに出力されます。

Windowsの場合はタスクマネージャのプロセスタブで表示列を追加すればPIDを確認できます。

ちなみにkillの方では最初に必ずFullGCが実行されるようなのですが、jmapではFullGCされてる気配はありませんでした。
実行結果はこんな感じです。

 num     #instances         #bytes  class name
———————————————————————
   1:         11881       23889944  [I
   2:        702688       22486016  java.util.concurrent.ConcurrentHashMap$Segment
   3:         97609       17855536  [C
   4:        702740       16865760  java.util.concurrent.locks.ReentrantLock$NonfairSync
   5:        702688       11524576  [Ljava.util.concurrent.ConcurrentHashMap$HashEntry;

メモリ内のインスタンス数とバイト数がみられるので、怪しいクラスを特定できます。

2.ヒープダンプ情報の確認

統計情報だけでは足りない場合、より詳細なヒープ情報を取得できます。

(JDK1.5) jmap -heap:format=b <pid>
(JDK1.6) jmap -dump:format=b,file=[出力先ファイルパス] <pid>

バイナリファイルが出力されるので、それを解析ツールを使って検証します。

ここからMemory Analyzerをダウンロード
http://www.eclipse.org/mat/downloads.php

Eclipseプラグイン版とスタンドアロンのアプリ版があります。 最初プラグイン版を試しましたが、いまいちよくわからなかったので今回はスタンドアロン版を使用しました。

メニューの
 File - Open Heap Dump
で先ほど出力したファイルを読み込みます。

Overviewタブに円グラフが表示されたので、一番大きいところをクリックして
 Java Basics - Open In Dominator Tree
ヒープ内のオブジェクトが表示されるので、Retained Heapが大きいオブジェクトを右クリックして
 Path To CG Roots - with all references
で、このオブジェクトがどこから参照されているかを見てみると、フレームワークが保持しているセッション用オブジェクト内のHashオブジェクトが大量に存在してました。

web.xmlでセッションのタイム時間を確認してみたところ、 なんとその記述がコメントになっていて指定されていませんでした orz

セッション時間のデフォルトは大体20、30分くらいだったと思うので、ためしにFullGC発生後に30分間放置して再度負荷をかけたら、大量にメモリが開放されていました。

まぁはまったときの原因なんて大体こんなもんですが、今回はヒープダンプとMemory Analyzerを覚えられたのはよかったなと。

3.参考

実は上記内容はほとんどこちらにも書いてありましたw
http://d.hatena.ne.jp/learn/20090218/p1

Memory Analyzerの使い方はこちらを参考にしました
http://tlync.hateblo.jp/entry/20111220/1324372308