Javaのガベージ・コレクションを知る：Javaパフォーマンスチューニング（2）（2/2 ページ）

» 2005年02月25日 00時00分公開

ガベージ・コレクションを分析する

　ガベージ・コレクションが実際にどのタイミングで発生しているかを知るには、JVMのオプション「-verbose:gc」を以下のように指定します。

$ java -verbose:gc ＜クラス名＞

　これにより、以下のようなガベージ・コレクションのログを記録することができます。

[GC 1419K->1159K(1984K), 0.0041208 secs]
[Full GC 1159K->727K(1984K), 0.0100906 secs]
[GC 1879K->1879K(3140K), 0.0006966 secs]
[Full GC 1879K->1303K(3140K), 0.0111883 secs]
[GC 3607K->3607K(5448K), 0.0001983 secs]
[Full GC 3607K->2455K(5448K), 0.0126519 secs]

Full GCの発生に注目する

　「GC」で始まる行は、Scavengeガベージ・コレクション（Scavenge GC）の発生を表します。一方、「Full GC」で始まる行は、Fullガベージ・コレクション（Full GC）を表します（この両者の違いについては次回説明します）。また「GC」あるいは「Full GC」のすぐ後には、以下のような数値が続きます。

1419K->1159K(1984K) , 0.0100906 secs

　上記のログは、JVM内のオブジェクト・サイズが「GC前は1419KB、GC後は1159KB」であることを示します。つまりこのGCでは260KBの領域が解放されたことになります。

　また丸カッコ内の数値は、「ヒープ内の空き領域は1984KB」という意味です。最後の数値は、このGCに要した時間です。

　これらのログを注意深く観察することで、JVM内部におけるガベージ・コレクションの挙動を把握することができます。例えば正常に動作するJVMの場合、Scavenge GCは1回当たり数ms～数十 ms程度で完了します。一方、Full GCの実行には数十 ms～数百 msを要し、ヒープ・サイズによっては数秒かかることもあります。

　このようにFull GCは、Scavenge GCに比べてけた違いに長い処理時間を要します。よって、上記の例のようにFull GCが頻繁に発生している場合（例えば1分間に1回以上）は、その頻度を抑える何らかの対策を講じなくてはなりません。通常は、Full GCが1秒以内に終了し、Scavenge GCと比較して少ない頻度で発生するようにチューニングします。例えば、Full GCが5～10分置きに発生し、Scavenge GCは5から10秒置きに発生するような間隔であれば、そのJVMの振る舞いは正常であるといえます。

　もしFull GCに1秒以上の時間が費やされていると、Javaプログラムはその間完全に停止することになり、パフォーマンスの問題を抱えていることが分かります。これを解決するには、JVMのオプションを指定して、ヒープ内部の各領域の利用度に応じたヒープ・サイズを指定します。この方法について詳しくは次回説明します。

　以上、今回は、Java言語におけるガベージ・コレクションの役割を解説し、その発生頻度をログに記録する方法を説明しました。次回は、JVMのヒープ・メモリの構造を説明し、パフォーマンスを最大限に引き出すためのチューニング方法を掘り下げる予定です。

コラム：HP JVMの拡張オプションの活用

　HP-UXに標準で付属するJVM「HP JVM」では、ガベージ・コレクションの詳細な振る舞いを記録するための拡張オプション「-Xverbosegc」が利用できます。同オプションは以下のように使用します。

$ java -Xverbosegc:file=myfile.out ＜クラス名＞

　これにより、「myfile.out」という名前のファイルにガベージ・コレクションのログを記録することができます。このファイル名は、自由に変更することができます。ちなみに、このオプションの指定によるパフォーマンスの低下は、ディスクへのファイル出力を除けば非常に小さなものです。よって、必要に応じて、実運用システムにも使用することができます。

　このオプション指定によって出力されるログには、以下のような内容が記録されます。

<GC: -1 21.040560 1 824 1 13369144 0 13369344 0 1703936 1703936 01206120 50331648 4793888 4793888 4980736 0.124737 >
< GC: -1 24.040994 2 80 1 13369344 0 13369344 1703936 1703936 17039361206120 5058264 50331648 5032840 5032840 5242880 1.896397 >
< GC: 2 28.602708 1 216 1 1109352 0 13369344 1703936 0 1703936 50582646780520 50331648 5242688 5242688 5242880 0.870284 >
< GC: -1 45.500549 3 656 32 13369136 0 13369344 0 805256 17039366780520 6780520 50331648 8720800 8720800 8916992 0.055405 >

　このログ内容をそのまま読んで理解することは困難です。そこでHPでは、ログをグラフィカルに表示する無償ツール「HPjtune」（用語解説参照）を提供しています。また併せて、ログを見やすく整形するためのスクリプト「processVerboseGC.awk」も提供しています。このスクリプトは、「java products for HP-UX」（http://www.hp.com/go/java/）からダウンロード可能です。このスクリプトを実行するには、以下のコマンドを入力します。

$ cat myfile.out |awk -f processVerboseGC.awk > output.txt

　これにより、以下のような読みやすい形態にログを変換することができます。

GC: Full GC required - reason: Old generation expanded on last scavenge
GC: Full 1.985317 s since last: 1.985317 s gc time: 96 ms
eden: 1834928->0/3670016 　　　survivor: 120576->0/262144
tenure: 2 　　　old: 3204992->2356088/3928064
GC: Scav 2.190710 s since last: 0.205393 s gc time: 4 ms
eden: 3669968->0/3670016　　　 survivor: 0->120720/262144
tenure: 32 　　　old: 2356088->2356088/3928064

　このログは、Javaプログラムの実行中に発生した3回のガベージ・コレクションを順番に示しています。その発生時刻は、Javaプログラムの開始時から経過した時間として、文字列「Full」もしくは「Scav」に続いて表示されています。また、その後には「eden」や「survivor」「tenure」「old」といった文字列が表示されていますが、これらの単語の意味は本連載で追って説明する予定です。

用語解説

■HPjtune

JVMのガベージ・コレクション（GC）を解析するためのツール。JVMから得られたプロファイリング・データに基づきGCの状況を分析し、パフォーマンスの改善に役立つ情報を提供する。GC時のリソース利用状況や、アプリケーションのパフォーマンスにGCが与える影響のグラフ表示、またユーザーが解析対象として選択したメトリクスのグラフ表示が可能。詳細情報は、以下のページを参照。

HPjtune（日本HP）

本記事は、HP-UX Developer Edgeに掲載された「連載 Javaパフォーマンスチューニング」を株式会社アットマーク・アイティおよび本記事の筆者が独自の判断のもとに加筆・修正したものです。

「次回」へ

「Javaパフォーマンスチューニング」バックナンバー