torutkのブログ

ソフトウェア・エンジニアのブログ

finalizeとJavaヒープメモリ

JavaGUIアプリケーション(ネイティブライブラリ使用)をしばらく実行していると、だんだん重くなり、JavaヒープメモリをJDKのjconsoleツールで調べると、上限に張り付きFull GCが頻繁に発生してますが、グラフが下がらないという状況がありました。

同じくJDKのjvisualvmツールでヒープに占めるオブジェクトを調査すると(「サンプラ」タブの「メモリー」ボタンを押し、ヒープヒストグラムを表示)、あるクラスのインスタンスが100万個以上と同数のjava.lang.ref.Finalizerが存在しています。
ロジック的なメモリリークではなく、GCのファイナライズに関して問題が生じているようです。問題のクラスは、ネイティブライブラリを使用していおり、jconsoleでFinalizerスレッドのダンプを見ると、そのクラスのfinalizeでネイティブ呼び出しをしています。

参考: ファイナライズの仕組みについて解説している記事がありました。

普通にGCで到達不能になっても、Finalizerスレッドでfinalizeが呼ばれるまではインスタンスを保持する必要があり、finalize呼び出しでJNI経由のネイティブコードを実行していると、短時間に大量にオブジェクトを生成した場合にFinalizerスレッドが追いつかないということがあるのかもしれません。

調査・解析に使用したツールなどのメモ

今回の問題を調査するにあたって、Java標準機能で間に合ってしまいました。

jconsole

調査対象のJavaアプリケーションを実行後、JDK標準ツールのjconsoleを実行します。起動後、接続するJavaプログラムを選択すると、CPU使用率、メモリ使用量、スレッド数、スレッドのスタックトレースなどがGUI上で確認できます。
GCの発生回数と累計時間もモニタできるので、まず最初にアプリケーションの状況を見るときはこれが便利です。

jconsoleからは、java.util.loggingのログレベルを制御することもできるので、アプリケーション実行途中でログ詳細を出したい、ということも可能です。結構便利です。なお、log4jの場合もlog4jライブラリに含まれているMBeanを初期化で設定しておけば、同様にログレベルを変更することができます。

jvisualvm

調査対象のJavaアプリケーションを実行後、JDK標準ツールのjvisualvmを実行します。jconsoleと同様、接続するJavaプログラムを選択すると、CPU使用率、メモリ使用量、スレッドなどの情報がGUI上で確認できます。jconsoleと機能が大分かぶっていますが、今回の調査では[サンプラ]タブの[メモリー]サンプリングでヒープヒストグラムをモニタしました。ヒープ使用量の多いクラス順に表示してくれるものです。

jvisualvmに別途Visual GCプラグインを入れると、世代別GCの動きがグラフィカルに見える楽しい機能があります。[ツール]メニュー>[プラグイン]で、[使用可能なプラグイン]タブからVisual GCをインストールします。

jmap

コマンドラインからヒープの使用状況を取得します。1分周期で状況を残したい、といったときに、コマンドラインから実行します。-histoオプションでヒストグラムをテキスト保存して推移を見るのについかいました。

jstat

コマンドラインからGCの活動状況・ヒープ使用量などを取得します。これも周期的に状況を残したいときに実行します。

jstack

コマンドラインから各スレッドのスタックトレースを取得します。

備考

やっかいなのは、ネイティブライブラリがWindowsのCOM形式のもので、JavaからCOMを呼び出すライブラリ経由で利用されているという状況です。いずれも出来合いのもの(いわゆるサードパーティ製ライブラリ)であり、手を入れることが難しいので困りました。