メモリリークトラブルシューティング記 – その3: 侍でヒープ使用量を確認

– その1: 自宅サーバがハング

– その2: フリーズの原因はガベージコレクション

– その3: 侍でヒープ使用量を確認

前回のエントリで、フリーズの原因が Full GC の頻発にあることまで書きました。

GC 、特にマーキングと呼ばれるオブジェクトが回収可能かどうかを確認する処理は重たいです。
Sun, HP, Apple, OpenJDK といったブランド/ベンダの JVM は世代別GC(Generational GC)と呼ばれるアルゴリズムを採用しています。
#最近の IBM JDK は Generational GC を選択することもできるようになっています

世代別 GC では VM のヒープ領域を大きく New 領域、Old 領域と分けておき、生成されたばかりのオブジェクトは New 領域に、長生きするオブジェクトは Old 領域にわけます。
長生きしているかどうかはオブジェクトの世代数(GCをくぐり抜けて生き続けた回数)で区別します。
普段の GC(マイナーGC)では New 領域のオブジェクトのみのマーキング、回収処理を行います。
以前 Old 領域に「昇格」したオブジェクトについてはマイナーGCは無関心です。

Full GC は一般的に Old 領域が一杯になったタイミング、または Permanent 領域と呼ばれるクラスの定義情報を格納している領域が一杯になったタイミングで発生します。
さて、今回の Full GC ログはいかがでしょうか。
取得した GC ログと、読み方を以下に示します。

※色々な情報が読み取れますが重要な箇所だけ注釈を書きました

残念ながら、この GC ログでは Old 領域も Permanent 領域もほぼ一杯になっているのでどちらの領域の枯渇が Full GC 発生のトリガになっているのかひと目ではわかりません。
この様な場合は GC ログメッセージを先頭から追っていって Old 領域と Permanent 領域の増加傾向を確認することになります。
Old 領域が足りない場合は多くの場合 Old 領域のヒープ使用量がぶれて、Permanent領域の使用量はほぼフラットになります。
Permanent領域が足りない場合は Permanent 領域、Old 領域両方の使用量がぶれます。
GC ログを目で追って確認したり、awk で処理して CSV 化して Excel で読み込んだり・・・とかは面倒なので今回は自作ツールである侍を使いました。

使い方は簡単、GCログを含むテキストファイルをドラッグ&ドロップで侍のウィンドウに渡すだけです。
すると「メモリ」という名前のタブが現れて、GCログの解析結果がビジュアル表示されます。

侍で解析した結果

上段が New 領域、中段が Old 領域、下段が Permanent領域になります。
するとどうでしょう、「昇格」したオブジェクトが Old 領域に運ばれては Full GC が発生し、なんとかして不要になったオブジェクトを回収しつつだましだまし VM が動いている様子が確認できました。
Permanent 領域はほぼフラットで微増も微減もしていません。
恐らく Old 領域が枯渇していますね。OutOfMemoryError が発生するのも時間の問題です。
ただ Full GC の処理が重たくてアプリケーションがほとんど稼働していないため OutOfMemoryError には至っていませんが。

実は今回 Permanent 領域のサイズは指定していなかったのでPermanent領域の最大サイズはデフォルトの 64mb になっています。
このことからも 60mb までしか確保されていない Permanent 領域はまだ余裕があると推測することもできます。

というわけで Old 領域に何が溜まっているのかを確認することにしました。

– その4: リーク箇所を確認する色々な方法

– その5: Memory Analyzer でヒープダンプを解析(最終回)