7.2.7 java.lang.System.gc()実行時におけるスタックトレース出力機能

Javaアプリケーションが以下のJavaメソッドを頻繁に実行すると、Java VMに負荷がかかり、アプリケーションの応答性能を低下させる要因になることがあります。

java.lang.System.gc()
java.lang.Runtime.gc()

以降、java.lang.System.gc()(以降、System.gc()と略する)で代表して説明します。

FJVMでは、Javaアプリケーション実行時にSystem.gc()メソッドの実行状態の確認ができるように、当該メソッドを実行したJavaスレッドのスタックトレースを出力する機能を「java.lang.System.gc()実行時におけるスタックトレース出力機能」として実装しています。
java.lang.System.gc()実行時におけるスタックトレース出力機能は、図1のオプションを指定した場合に有効となります。

本機能が有効な場合、Javaアプリケーション内でSystem.gc()メソッドが実行された場合には、当該メソッドを実行したJavaスレッドのスタックトレース情報が、図2のような形で標準出力へ出力されます。
なお、標準出力への出力結果は、FJVMのログ情報としてファイルへも格納されます。また“-verbose:gc”オプション指定などでガーベジコレクション処理の結果ログ出力を指定していた場合は、java.lang.System.gc()実行時におけるスタックトレース出力後に出力された結果ログ出力も、合わせてファイルへ格納されます。ファイル名や格納先はJava VM異常終了時のログ出力時と同じです。“7.2.11 FJVMログ”を参照してください。

図1 java.lang.System.gc()実行時におけるスタックトレース出力機能を有効にするオプション

-XX:+PrintJavaStackAtSystemGC

図2 java.lang.System.gc()実行時におけるスタックトレース出力機能による出力例

【JDK/JRE 1.4または5.0の場合】

"main" prio=5 tid=0x0002d0a8 nid=0x1 runnable [ffbee000..ffbeee7c]
                         at java.lang.Runtime.gc(Native Method)
                         at java.lang.System.gc(System.java:737)
                         at SystemGC.main(SystemGC.java:8)
 
 "main" prio=5 tid=0x0002d0a8 nid=0x1 runnable [ffbee000..ffbeee7c]
                         at java.lang.Runtime.gc(Native Method)
                         at SystemGC.foo(SystemGC.java:4)
                         at SystemGC.main(SystemGC.java:10)

【JDK/JRE 6の場合】

"main" prio=10 tid=0x087c1c00 nid=0xd2a runnable [0xb75ab000..0xb75ab214]
   java.lang.Thread.State: RUNNABLE
                        at java.lang.Runtime.gc(Native Method)
                        at java.lang.System.gc(System.java:928)
                        at SystemGC.main(SystemGC.java:8)

"main" prio=10 tid=0x087c1c00 nid=0xd2a runnable [0xb75ab000..0xb75ab214]
   java.lang.Thread.State: RUNNABLE
                        at java.lang.Runtime.gc(Native Method)
                        at SystemGC.foo(SystemGC.java:4)
                        at SystemGC.main(SystemGC.java:10)

図2の出力例の場合、SystemGC.mainからjava.lang.System.gc()が実行され、SystemGC.fooからjava.lang.Runtime.gc()が実行されたことを確認することができます。

JDK/JRE 6からスタックトレース情報にスレッドの状態を表す情報（トレース情報の前の行）が表示されるようになりました。

図中の例では「java.lang.Thread.State: RUNNABLE」となっていますが、"RUNNABLE"の部分が、"NEW"、"TIMED_WAITING (sleeping)"、"WAITING (on object monitor)"、"TIMED_WAITING (on object monitor)"、"WAITING (parking)"、"TIMED_WAITING (parking)"、"BLOCKED (on object monitor)"、"TERMINATED"、"UNKNOWN"などの表示の場合があります。