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

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

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

-verbose:gc

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

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

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

GCの種類：

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

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

CMS付きパラレルGCを使用している場合は、以下の出力フォーマットのGCログもあります。

[GC ヒープ使用量(ヒープのサイズ), マーク処理時間]

このフォーマットで出力された場合は、CMS-GC処理のinitialマーク処理またはfinalマーク処理が実行されたことを示します。

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

例

GCログの出力例

[GC 80229K->31691K(259776K), 0.4795163 secs]
[FullGC 57654K->4623K(259776K), 0.3844278 secs]

なおFJVMでは、GC処理の結果ログ出力機能の強化を行っています。より詳細なGC処理の結果ログ情報を得る場合には、当該機能を使用してください。詳細は、“9.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処理の結果ログの場合は、「GC処理の実行開始時間」のフォーマットを、ログ出力における「9.5.7 ログ出力における時間情報のフォーマット指定機能」により指定できます。）
- 格納先ファイル名の指定には、絶対パスや相対パスのディレクトリ名を付加した形式も可能です。
- 格納先ファイル名の中にあるディレクトリが存在しないなど、何らかの理由で指定された格納先ファイルにアクセスできなかった場合、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アプリケーションを実行する場合に、必要に応じて指定してください。

FJVMでは、“-verbose:gc”オプション指定時に出力されるガーベジコレクション(GC)処理の結果ログを、より詳細に出力する「ガーベジコレクション処理の結果ログ出力機能の強化」を行っています。

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

-XX:+UseFJverbose

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

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

$1: [$2, [$3 : $4->$5($6)], [$7 : $8->$9($10)] $11->$12($13), [$14 : $15->$16($17)], $18 secs]

$1: GC処理の実行開始時間(ログ出力時の時間): GC処理の実行開始時間(ログ出力時の時間)を示します。
ログ出力時の時間のフォーマットは、ログ出力における「9.5.7 ログ出力における時間情報のフォーマット指定機能」により指定できます。
デフォルトは、「Java VMが起動されてからの経過時間(秒)」です。

$2: GC種別

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

GC
New世代領域を対象とするGC処理(NewGC処理またはマイナーGC処理)における結果情報です。
Full GC
Javaヒープ域全体(メモリ割り当てプール(New世代領域、Old世代領域)およびPermanent世代領域)を対象とするGC処理(FullGC処理)における結果情報です。
Full GC*
使用されているGC処理がシリアルGCまたはCMS付きパラレルGCの場合で、かつ、直前に実行されたNewGC処理では十分な空き領域が確保できず、そのNewGC処理に続けて実行されたFullGC処理における結果情報です("Full GC"の後に"*"の付く表示になります)。
なおこの名称は“-verbose:gc”オプションだけを指定した場合には出力されません(単に"Full GC"として出力されます)。
CMS initial-mark
Old世代領域を対象とするCMS-GC処理のうち、initialマーク処理における結果情報です。
CMS-GCでは、不要オブジェクトを検出するために行う処理(initialマーク処理)を実行する際、極わずかな時間だけJavaアプリケーションを停止させます。
注)不要オブジェクトの検出処理だけであるため、GC処理開始前後での各世代領域におけるオブジェクト量に変化はありません。
CMS remark
Old世代領域を対象とするCMS-GC処理のうち、finalマーク処理における結果情報です。
CMS-GCでは、不要オブジェクトを検出するために行う処理(finalマーク処理)を実行する際、極わずかな時間だけJavaアプリケーションを停止させます。
注)不要オブジェクトの検出処理だけであるため、GC処理開始前後での各世代領域におけるオブジェクト量に変化はありません。

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

$14: Permanent世代領域の識別名

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

Perm: シリアルGCの場合
PSPermGen: パラレルGCの場合
CMS Perm: CMS付きパラレルGCの場合

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

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

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

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

参考

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

GC処理の結果ログとして出力される情報の拡張形式(CMS-GCの開始)

$1: CMS start

$1: CMS-GC処理の実行開始時間(ログ出力時の時間): CMS-GC処理の実行開始時間(ログ出力時の時間)を示します。
ログ出力時の時間のフォーマットは、ログ出力における「9.5.7 ログ出力における時間情報のフォーマット指定機能」により指定できます。
デフォルトは、「Java VMが起動されてからの経過時間(秒)」です。

GC処理の結果ログとして出力される情報の拡張形式(FullGC発生によるCMS-GCの終了要求)

$1: CMS stop-req

$1: CMS-GC処理の終了要求時点(ログ出力時の時間)

Full GC要求発生時にCMS-GC処理が実行中であった場合、CMS-GC処理の終了要求時点(ログ出力時の時間)を示します。
ログ出力時の時間のフォーマットは、ログ出力における「9.5.7 ログ出力における時間情報のフォーマット指定機能」により指定できます。
デフォルトは、「Java VMが起動されてからの経過時間(秒)」です。

注)CMS-GC処理が動作している最中にJavaヒープ不足やjava.lang.System.gc()実行などによりFull GC要求が発生した場合、Full GC処理は、実行中のCMS-GC処理の終了を待ってから開始されます。その際、CMS-GCが処理しているデータの整合性を維持させるため、CMS-GC処理の終了は強制的な打ち切り終了ではなく、CMS-GC内で打ち切り可能な処理まで完了させてからの終了になります。そのため、CMS-GC処理が実行中であった場合、Full GC処理要求の発生から実際にFull GC処理が開始されるまでに、ある程度の時間差が生じる可能性があります。

なおCMS-GC処理の終了要求時点からCMS-GC処理の実行が終了するまで、Javaアプリケーションとしての動作は停止します。そのため、CMS-GC処理の終了要求時点からFull GC処理の実行完了までが、この出力があった場合のFull GC処理によるJavaアプリケーション動作の実際の停止期間となります。

GC処理の結果ログとして出力される情報の拡張形式(CMS-GCの終了)

パターン1：
CMS-GCの対象が「Old世代領域内」の場合
$1: CMS stop($2), [CMS : $3->$4($5)], $9 secs
CMS-GCの対象が「Old世代領域内およびPermanent世代領域内」の場合
$1: CMS stop($2), [CMS : $3->$4($5)], [CMS Perm : $6->$7($8)], $9 secs
パターン2：
$1: CMS stop($2), $9 secs

$1: CMS-GC処理の実行終了時間(ログ出力時の時間): CMS-GC処理の実行終了時間(ログ出力時の時間)を示します。
ログ出力時の時間のフォーマットは、ログ出力における「9.5.7 ログ出力における時間情報のフォーマット指定機能」により指定できます。
デフォルトは、「Java VMが起動されてからの経過時間(秒)」です。

$2: 終了コード

CMS-GC処理の実行結果に対する終了コードを示します。
終了コードの違いにより、情報の出力形式パターンが異なります。
終了コードの種類および意味は以下のとおりです。

00: CMS-GC処理が終了しました。
Old世代領域内またはOld世代領域内およびPermanent世代領域内で検出済の不要オブジェクトは回収しました。
パターン1の出力形式で情報が出力されます。
10: Javaヒープ不足によるFull GC要求があったため、実行中のCMS-GC処理を終了しました。
Old世代領域内またはOld世代領域内およびPermanent世代領域内で検出済の不要オブジェクトは回収しました。
パターン1の出力形式で情報が出力されます。
20: java.lang.System.gc()などの外部要因によるFull GC要求があったため、実行中のCMS-GC処理を終了しました。
Old世代領域内またはOld世代領域内およびPermanent世代領域内で検出済の不要オブジェクトは回収しました。
パターン1の出力形式で情報が出力されます。
11: Javaヒープ不足によるFull GC要求があったため、実行中のCMS-GC処理を終了しました。
Old世代領域内またはOld世代領域内およびPermanent世代領域内の不要オブジェクトは回収していません。
パターン2の出力形式で情報が出力されます。
21: java.lang.System.gc()などの外部要因によるFull GC要求があったため、実行中のCMS-GC処理を終了しました。
Old世代領域内またはOld世代領域内およびPermanent世代領域内の不要オブジェクトを回収していません。
パターン2の出力形式で情報が出力されます。

$3: CMS-GC処理前のオブジェクト量(Old世代領域): CMS-GC処理実行前のOld世代領域に存在したオブジェクトの総量(バイト)です。
通常はCMS-GC処理のfinalマーク処理実行時のOld世代領域に存在したオブジェクトの総量と等しくなります。
finalマーク処理実行時のOld世代領域に存在したオブジェクトの総量と等しくない場合は、CMS-GCによる不要オブジェクトの回収処理前にNew世代領域用GCが実行された、またはJavaアプリケーションの実行によりOld世代領域にオブジェクトが割り当てられたことを示します。

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

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

$6: CMS-GC処理前のオブジェクト量(Permanent世代領域): CMS-GC処理実行前のPermanent世代領域に存在したオブジェクトの総量(バイト)です。
通常はfinalマーク実行時のPermanent世代領域に存在したオブジェクトの総量と等しくなります。
finalマーク処理実行時のPermanent世代領域に存在したオブジェクトの総量と等しくない場合は、CMS-GCによる不要オブジェクトの回収処理前に、Javaアプリケーションの実行によりPermanent世代領域にオブジェクトが割り当てられたことを示します。

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

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

$9: CMS-GC処理実行時間

CMS-GC処理実行に要した時間(秒)です(CMS-GC開始からの経過時間です)。

注意

有効なGC処理

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

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

注意

ログ出力量の増加

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

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

ログの見方

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

例

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

23.646: [Full GC, [PSYoungGen : 1584K->0K(5504K)], [PSOldGen : 57764K->26302K(58304K)] 59348K->26302K(63808K), [PSPermGen : 4655K->4655K(16384K)], 0.1353549 secs]

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

Java VMが起動されてから23.646秒後にFullGC処理が実行された。
使用されているGC処理はパラレルGCである。
GC処理後のNew世代領域の大きさは5504KBである。
GC処理により、New世代領域に存在するオブジェクト量は1584KBから0KBになった。
（不要オブジェクトが削除され、また必要に応じてOld世代領域へ生存オブジェクトが移動した）
GC処理後のOld世代領域の大きさは58304KBである。
GC処理により、Old世代領域に存在するオブジェクト量は57764KBから26302KBになった。
（不要オブジェクトが削除され、また必要に応じてNew世代領域から生存オブジェクトが移動してきた）
GC処理後のメモリ割り当てプールの大きさは63808KBである。
GC処理により、メモリ割り当てプールに存在するオブジェクト総量は59348KBから26302KBになった。
（不要オブジェクトが削除された）
GC処理後のPermanent世代領域の大きさは16384KBである。
GC処理により、Permanent世代領域に存在するオブジェクト量は変化していない。
GC処理に要した時間は0.1353549秒である。

例

GC処理の結果ログとして出力される情報の拡張形式の出力例(CMS付きパラレルGCの場合-1)

150.207: CMS start
150.208: [CMS initial-mark, [ParNew : 1863K->1863K(14784K)], [CMS : 53791K->53791K(65536K)] 55654K->55654K(80320K), [CMS Perm : 4664K->4664K(16384K)], 0.0030212 secs]
150.351: [GC, [ParNew : 14782K->1598K(14784K)], [CMS : 53791K->57981K(65536K)] 68573K->59579K(80320K), [CMS Perm : 4664K->4664K(16384K)], 0.0328537 secs]
150.466: [CMS remark, [ParNew : 8277K->8277K(14784K)], [CMS : 57981K->57981K(65536K)] 66258K->66258K(80320K), [CMS Perm : 4664K->4664K(16384K)], 0.0097905 secs]
150.549: [GC, [ParNew : 14782K->1598K(14784K)], [CMS : 50163K->54371K(65536K)] 64946K->55969K(80320K), [CMS Perm : 4664K->4664K(16384K)], 0.0303271 secs]
150.583: CMS stop(00), [CMS : 57981K->54200K(65536K)], 0.3753996 secs

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

使用されているGC処理はCMS付きパラレルGC(CMS-GCの対象はOld世代領域)である。
Java VMが起動されてから150.207秒後にCMS-GC処理が開始され、150.583秒後に終了した。
終了したCMS-GCにより不要オブジェクトが回収された。
CMS-GC処理後のOld世代領域の大きさは65536KBである。
CMS-GC処理により、Old世代領域に存在するオブジェクト量は57981KBから54200KBになった。
CMS-GC処理に要した時間は0.3753996秒である。
CMS-GC処理中にNew世代領域用GC処理が実行された。またその実行開始は、遅延している可能性がある。

例

GC処理の結果ログとして出力される情報の拡張形式の出力例(CMS付きパラレルGCの場合-2)

137.803: CMS start
137.804: [CMS initial-mark, [ParNew : 206690K->206690K(314560K)], [CMS : 655731K->655731K(699072K)] 862421K->862421K(1013632K), [CMS Perm : 3892K->3892K(16384K)], 0.4101250 secs]
139.069: [GC, [ParNew : 279616K->34943K(314560K)], [CMS : 655731K->673280K(699072K)] 935347K->708223K(1013632K), [CMS Perm : 3892K->3892K(16384K)], 0.2177910 secs]
142.140: CMS stop-req
142.501: CMS stop(11), 4.6984060 secs
142.501: [Full GC, [ParNew : 314559K->0K(314560K)], [CMS : 673280K->657037K(699072K)] 987839K->657037K(1013632K), [CMS Perm : 3892K->3892K(16384K)], 1.8642510 secs]

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

使用されているGC処理はCMS付きパラレルGC(CMS-GCの対象はOld世代領域)である。
Java VMが起動されてから137.803秒後にCMS-GC処理が開始され、142.501秒後に終了した。
Java VMが起動されてから142.140秒後にFullGC要求があり、そのため実行中のCMS-GCが終了した。
終了したCMS-GCによる不要オブジェクト回収は実行されていない。
CMS-GC処理の終了要求時点(142.140)からCMS-GC処理の実行が終了(142.501)するまでの0.361秒、および142.501に実行開始したFullGCの実行時間1.8642510秒の合計2.225251秒の間、Javaアプリケーション動作が停止された。