10.2.6 ガーベジコレクションのログ出力

ガーベジコレクション(GC)のログを採取する場合は、以下のオプションを指定します。

GC処理の結果ログを出力するオプション

-verbose:gc

本オプションの指定により、GCが発生するたびに、GC処理の結果ログが標準出力へ1行ずつ出力されます。

GCログの出力フォーマット

[GCの種類 (GCの発生理由) GC前のヒープ使用量->GC後のヒープの使用量(ヒープのサイズ), GCの処理時間]

GCの種類：

“GC”の場合はマイナーGC(またはNewGC処理)で、“FullGC”の場合はFullGCであることを示します。

なお“Javaヒープの中のメモリ割り当てプール”を“ヒープ”と略記しています。

GCの発生理由：

GCの発生理由を表す文字列（内部制御の情報）が表示されます。

例. System.gc()/Allocation Failure/Ergonomics

例

GCログの出力例

[Full GC (System.gc()) 911K->911K(251392K), 0.0126174 secs]
[GC (Allocation Failure) 146967K->100836K(251392K), 0.1611865 secs]

より詳細なGC処理の結果ログ情報を得る場合は、“10.2.6.1 ガーベジコレクション処理の結果ログ詳細出力機能”を参照してください。

注意

ログ出力量の増加

本オプションの指定により、ログ出力が増大します。
本オプションを指定する場合は、ログ出力量についての注意が必要です。

New世代領域の使われ方

NewGC処理では、New世代領域を「eden space」、「from space」および「to space」の3つの内部領域に細分割し、当該領域上において、一般に世代別GC制御と言われる制御方法を用いて、Javaアプリケーションが生成要求したオブジェクトを管理・制御しています。
このうち、「from space」および「to space」は、Java VMがNewGC処理を行う際の作業域的な役割を持つ領域となっています。そのため、「from space」および「to space」の各領域が占める大きさのうち、Javaアプリケーションからのオブジェクト生成要求のために使用される大きさは、その領域の一部分だけとなります。
そのため、ガーベジコレクションのログ出力において、メモリ割り当てプールやNew世代領域に空きがあるように見える場合であっても、実際には空きがない場合があります（空きがあるように見える場合であっても、その差は、NewGC処理用の作業域的な役割で使用済となっている場合があります）。

クラスのアンロード情報

Javaアプリケーションがクラスのアンローディング処理を行っていた場合に、FullGC処理中に該当するクラスのアンロード情報”[Unloading class アンロードされたクラス名]”を結果ログ出力の途中に挿入したい場合は、以下のオプションを指定してください。

GC処理の結果ログに対してクラスのアンロード情報を出力するオプション
-XX:+ClassUnloadingInfo

GC処理の結果ログの格納先ファイルを指定するオプション
-Xloggc:GC処理の結果ログの格納先ファイル名
GC処理の結果ログおよびクラスのインスタンス情報を、標準出力ではなく、指定したファイルへ出力先を切り換えることができます。
- このオプションを指定すると、自動的に“-verbose:gc”オプションも指定したと見做されます。そのため、“-verbose:gc”オプションの指定がない場合でも、GC処理の結果ログが出力され、また、ガーベジコレクション処理の結果ログ詳細出力機能を使用することもできます。
  なお、“-Xloggc”オプション指定により出力されたGC処理の結果ログの先頭には、「Java VMが起動されてからの経過時間(秒)」が「GC処理の実行開始時間」として自動的に付加されます（以下の形式で出力されます）。
  GC処理の実行開始時間: GC処理の結果ログ(「GCログの出力フォーマット」と同じ)
  「GC処理の実行開始時間」のフォーマットは変更できません。
- 格納先ファイル名の指定には、絶対パスや相対パスのディレクトリ名を付加した形式も可能です。
- 格納先ファイル名の中にあるディレクトリが存在しないなど、何らかの理由で指定された格納先ファイルにアクセスできなかった場合、GC処理の結果ログは出力されません。
注意
Interstage Application Server配下でJavaアプリケーションを実行する際にオプションを指定した場合、以下の問題が発生します。
- オプションによるファイル出力処理には、ログローテーションなどの世代管理機能はありません。何らかの理由でJavaプロセスが自動的に再起動した場合、格納先として同じファイルが用いられることになるため、再起動後のGC処理の結果ログで再起動前の結果ログが上書きされ、ログ情報として使えなくなります。
- Javaアプリケーションを複数のプロセスで多重動作させる場合、同一のオプション定義で複数のプロセスが動作します。そのため、複数のプロセスから同じファイルに対してGC処理の結果ログを書き込むことになり、ログ情報として使えなくなります。
- Interstage Application Server配下でJavaアプリケーションを実行する際のログの出力先は、Interstage Application Serverとしての制御により、出力先ファイルが管理されています。オプション指定でGC処理の結果ログが別のファイルとなった場合、エラー発生時に、他のエラー情報とGC処理の結果ログが分離することになるため、エラーの解析が難しくなる場合があります。
そのため、Interstage Application Server配下でJavaアプリケーションを実行する場合には、上記のオプションを指定しないでください。上記のオプションは、Interstage Application Serverとは関係しない単独のJavaアプリケーションを実行する場合に、必要に応じて指定してください。

“-verbose:gc”オプション指定時に出力されるガーベジコレクション(GC)処理の結果ログを、より詳細に出力する機能について説明します。

GC処理の結果ログとして出力される情報を拡張するオプション

-XX:+PrintGCDetails

上記のオプションを指定することにより、GC処理の結果ログとして出力される情報が、「GC処理の結果ログとして出力される情報の拡張形式」に示す形式に拡張されます。

-XX:+PrintGCTimeStamps

上記のオプションを指定することにより、GC処理の結果ログにタイムスタンプを付加する形式に拡張されます。

上記２つのオプションを指定した場合に表示されるGC処理の結果ログの形式を以下に示します。

GC処理の結果ログとして出力される情報の拡張形式

$1: [$2 ($3) [$4 : $5->$6($7)] [$8 : $9->$10($11)] $12->$13($14), [$15 : $16->$17($18)], $19 secs] [Times: user=$20 sys=$21, real=$22 secs]

$1: GC処理の実行開始時間(ログ出力時の時間): GC処理の実行開始時間(ログ出力時の時間)を示します。
時間は、起動されてからの経過時間(秒)です。

$2: GC種別

実行したGC処理の種別を以下の名称で示します。

GC
New世代領域を対象とするGC処理(NewGC処理またはマイナーGC処理)における結果情報です。
Full GC
Javaヒープ域全体(メモリ割り当てプール(New世代領域、Old世代領域)およびメタスペース)を対象とするGC処理(FullGC処理)における結果情報です。
CMS initial-mark
Old世代領域を対象とするCMS-GC処理のうち、initialマーク処理における結果情報です。
CMS-GCでは、不要オブジェクトを検出するために行う処理(initialマーク処理)を実行する際、極わずかな時間だけJavaアプリケーションを停止させます。
注)不要オブジェクトの検出処理だけであるため、GC処理開始前後での各世代領域におけるオブジェクト量に変化はありません。
CMS remark
Old世代領域を対象とするCMS-GC処理のうち、finalマーク処理における結果情報です。
CMS-GCでは、不要オブジェクトを検出するために行う処理(finalマーク処理)を実行する際、極わずかな時間だけJavaアプリケーションを停止させます。
注)不要オブジェクトの検出処理だけであるため、GC処理開始前後での各世代領域におけるオブジェクト量に変化はありません。
CMS-concurrent-phase-start/CMS-concurrent-phase
CMS-GCスレッドで実行される各CMS-GC処理phaseの開始と終了における情報です。
phaseには以下があります。これらのphaseは、Javaアプリケーションを停止することなく、CMS-GCスレッドで実行されます。
- mark
- preclean
- sweep
- reset
- abortable-preclean
注意
CMS付きパラレルGCのログ
GC種別が"CMS-concurrent-phase-start"および"CMS-concurrent-phase"のログは、CMS-GCスレッドで実行された CMS-GCの内部処理のログです (phaseは、mark/preclean/sweep/reset/abortable-preclean) 。このログの対象となるCMS-GC処理は、Javaアプリケーションを停止することなく動作するために通常は意識する必要はありません。このログは、保守サポート向けの情報（CMS-GCの処理ロジックを理解した高度なスキルを必要とする情報です）。このため、phaseの説明は省略しています。

$3: GCの発生理由

GCの発生理由を表す文字列（内部制御の情報）が表示されます。

例. System.gc()/Allocation Failure/Ergonomics

$4: New世代領域の識別名

New世代領域の識別名を示します。
使用されているGC処理の違いにより、以下の識別名が出力されます。

DefNew: シリアルGCの場合
PSYoungGen: パラレルGCの場合
ParNew: CMS付きパラレルGCの場合

$5: GC処理前のオブジェクト量(New世代領域): GC処理実行前のNew世代領域に存在したオブジェクトの総量(バイト)です。

$6: GC処理後のオブジェクト量(New世代領域): GC処理実行後のNew世代領域に存在するオブジェクトの総量(バイト)です。

$7: New世代領域の大きさ: New世代領域の大きさ(バイト)です。
注)使用されているGC処理がシリアルGC、パラレルGCまたはCMS付きパラレルGCの場合は、この大きさに「to space」領域の大きさが含まれません。
（シリアルGC、パラレルGCまたはCMS付きパラレルGCの場合、GC処理はNew世代領域を「eden space」、「from space」および「to space」の3つの内部領域に細分割して制御しています。）

$8: Old世代領域の識別名

Old世代領域の識別名を示します。
使用されているGC処理の違いにより、以下の識別名が出力されます。

Tenured: シリアルGCの場合
ParOldGen: パラレルGCの場合
CMS: CMS付きパラレルGCの場合

$9: GC処理前のオブジェクト量(Old世代領域): GC処理実行前のOld世代領域に存在したオブジェクトの総量(バイト)です。

$10: GC処理後のオブジェクト量(Old世代領域): GC処理実行後のOld世代領域に存在するオブジェクトの総量(バイト)です。

$11: Old世代領域の大きさ: Old世代領域の大きさ(バイト)です。

$12: GC処理前のオブジェクト量(メモリ割り当てプール): GC処理実行前のメモリ割り当てプールに存在したオブジェクトの総量(バイト)です。
$5+$9の値です。

$13: GC処理後のオブジェクト量(メモリ割り当てプール): GC処理実行後のメモリ割り当てプールに存在するオブジェクトの総量(バイト)です。
$6+$10の値です。

$14: メモリ割り当てプールの大きさ: メモリ割り当てプールの大きさ(バイト)です。
$7+$11の値です。
注意
使用されているGC処理がシリアルGC、パラレルGCまたはCMS付きパラレルGCの場合は、この大きさにNew世代領域の「to space」領域の大きさが含まれません。
（シリアルGC、パラレルGCまたはCMS付きパラレルGCの場合、GC処理はNew世代領域を「eden space」、「from space」および「to space」の3つの内部領域に細分割して制御しています。）

$15: メタスペースの識別名

メタスペースの識別名です。
使用されているGC処理の違いに関わらず、以下の識別名が出力されます。

Metaspace

$16: GC処理前のオブジェクト量(メタスペース): GC処理実行前のメタスペースに存在したオブジェクトの総量(バイト)です。

$17: GC処理後のオブジェクト量(メタスペース): GC処理実行後のメタスペースに存在するオブジェクトの総量(バイト)です

$18: メタスペースの大きさ: メタスペースの大きさ(バイト)です。

$19: GC処理実行時間: GC処理実行に要した時間(秒)です。
注)GC処理は、Javaアプリケーションとしての動作を停止させて実行されます。

$20: CPU時間（ユーザ時間）: GC処理期間中に、GC処理が使用したCPU時間（秒）です。

$21: CPU時間（システム時間）: GC処理期間中に、システム（ＯＳ）が使用したCPU時間（秒）です。

$22: 実時間

GC処理にかかった実時間（秒）です。

注意

有効なGC処理

このオプション指定により出力形式が拡張されるのは、使用するGC処理が以下の場合です。

シリアルGC
パラレルGC
CMS付きパラレルGC

ログ出力量の増加

本オプションの指定により、ログ出力が増大します。

本オプションを指定する場合は、ログ出力量についての注意が必要です。

参考

$2、$3、$12、$13、$14、および$19に対する出力情報は、GC処理の結果ログ出力機能として“-verbose:gc”オプションだけを指定した際に出力される情報と対応します。

注意

マイナーGCの場合、Old世代領域の情報[$8 : $9->$10($11)] および、メタスペースの情報[$15 : $16->$17($18)]は出力されません。

ログの見方

GC処理の結果ログとして出力される情報の拡張形式の出力例を示します。

例

GC処理の結果ログとして出力される情報の拡張形式の出力例

19.980: [Full GC (Ergonomics) [PSYoungGen: 9664K->0K(164352K)] [ParOldGen: 174043K->120589K(201728K)] 183707K->120589K(366080K), [Metaspace: 7696K->7696K(1056768K)], 0.3491370 secs] [Times: user=0.68 sys=0.01, real=0.35 secs]

この出力情報から、以下のことが分かります。

Java VMが起動されてから19.980秒後にFullGC処理が実行された。
使用されているGC処理はパラレルGCである。
GC処理後のNew世代領域の大きさは164352KBである。
GC処理により、New世代領域に存在するオブジェクト量は9664KBから0KBになった。
（不要オブジェクトが削除され、また必要に応じてOld世代領域へ生存オブジェクトが移動した）
GC処理後のOld世代領域の大きさは201728KBである。
GC処理により、Old世代領域に存在するオブジェクト量は174043KBから120589KBになった。
（不要オブジェクトが削除され、また必要に応じてNew世代領域から生存オブジェクトが移動してきた）
GC処理後のメモリ割り当てプールの大きさは(366080KB)である。
GC処理により、メモリ割り当てプールに存在するオブジェクト総量は183707KBから120589KBになった。
（不要オブジェクトが削除された）
GC処理後のメタスペースの大きさは1056768KBである。
GC処理により、メタスペースに存在するオブジェクト量は変化していない。
GC処理に要した時間は0.3491370秒である。
GC処理に使用したCPU時間のうち、ユーザ時間は0.68秒で、システム時間は0.01秒である。また、実時間は0.35秒である。