ガーベジコレクション(GC)のログを採取する場合は、以下のオプションを指定します。
GC処理の結果ログを出力するオプション
-verbose:gc |
本オプションの指定により、GCが発生するたびに、GC処理の結果ログが標準出力へ1行ずつ出力されます。
GCログの出力フォーマット
[GCの種類 (GCの発生理由) GC前のヒープ使用量->GC後のヒープの使用量(ヒープのサイズ), GCの処理時間] |
“GC”の場合はマイナーGC(またはNewGC処理)で、“FullGC”の場合はFullGCであることを示します。
なお“Javaヒープの中のメモリ割り当てプール”を“ヒープ”と略記しています。
GCの発生理由を表す文字列（内部制御の情報）が表示されます。
例. System.gc()/Allocation Failure/Ergonomics
例
GCログの出力例
[Full GC (System.gc()) 911K->911K(251392K), 0.0126174 secs] |
より詳細なGC処理の結果ログ情報を得る場合は、“7.4.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処理用の作業域的な役割で使用済となっている場合があります）。
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処理の結果ログとして出力される情報の拡張形式」に示す形式に拡張されます。
上記のオプションを指定することにより、GC処理の結果ログにタイムスタンプを付加する形式に拡張されます。
-XX:+PrintGCTimeStampsは、タイムスタンプを「Java VMが起動されてからの経過時間(秒)」で示します。
例) 19.980:
-XX:+PrintGCDateStampsは、タイムスタンプを「日時(iso8601フォーマット)」で示します。
例) 2018-03-23T16:49:06.842+0900:
なお、-XX:+PrintGCTimeStampsと-XX:+PrintGCDateStampsを同時に指定した場合は、タイムスタンプを「日時(iso8601フォーマット)」、「Java VMが起動されてからの経過時間(秒)」の順で出力します。
例) 2018-03-23T16:49:06.842+0900: 19.980:
上記のオプションを指定した場合に表示されるGC処理の結果ログの形式を以下に示します。
GC処理の結果ログとして出力される情報の拡張形式
マイナーGCの場合
$1: [$2 ($3) $1a: [$4: $5->$6($7), $19a secs] $12->$13($14), $19 secs] [Times: user=$20 sys=$21, real=$22 secs] |
FullGCの場合
$1: [$2 ($3) $1a: [$4: $5->$6($7), $19a secs] $1b: [$8: $9->$10($11), $19b secs] $12->$13($14), [$15: $16->$17($18)], $19 secs] [Times: user=$20 sys=$21, real=$22 secs] |
GC処理の実行開始時間(ログ出力時の時間)を示します。
$1aは、$4の世代領域のGC処理の実行開始時間(ログ出力時の時間)を示します。
$1bは、$8の世代領域のGC処理の実行開始時間(ログ出力時の時間)を示します。
パラレルGCの場合、$1a、$1bは表示されません。
時間の出力形式は、上記の"-XX:+PrintGCTimeStamps"、"-XX:+PrintGCDateStamps"の説明を参照してください。
実行したGC処理の種別を以下の名称で示します。
GC
New世代領域を対象とするGC処理(NewGC処理またはマイナーGC処理)における結果情報です。
マイナーGCの発動を経由してFullGCが処理される場合があります。その場合、GC種別がマイナーGCの名称となっていますが、FullGCも追加されたフォーマットとなります。
Full GC
Javaヒープ域(New世代領域、Old世代領域)、およびメタスペースを対象とする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処理開始前後での各世代領域におけるオブジェクト量に変化はありません。
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の説明、および、ログの形式の説明は省略しています。
GCの発生理由が"CMS Initial Mark"および"CMS Final Remark"のログは、上記の「GC処理の結果ログとして出力される情報の拡張形式」と異なります。極わずかな時間だけJavaアプリケーションを停止させますが、"[GC" のかっこに対応する終わりのかっこ"]" の直前に出力されているGC処理実行時間を参照してください。
以下の例の場合、"0.0024809 secs"がGC処理実行時間になります。
例. 4.317: [GC (CMS Initial Mark) [1 CMS-initial-mark: 34216K(57028K)] 41282K(135684K), 0.0024809 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
その他の種別のログは、保守サポート向けの情報のため（CMS-GCの処理ロジックを理解した高度なスキルを必要とする情報です）、説明を省略しています。
GCの発生理由を表す文字列（内部制御の情報）が表示されます。
例. System.gc()/Allocation Failure/Ergonomics
New世代領域の識別名を示します。
使用されているGC処理の違いにより、以下の識別名が出力されます。
DefNew: シリアルGCの場合
PSYoungGen: パラレルGCの場合
ParNew: CMS付きパラレルGCの場合
GC処理実行前のNew世代領域に存在したオブジェクトの総量(バイト)です。
GC処理実行後のNew世代領域に存在するオブジェクトの総量(バイト)です。
New世代領域の大きさ(バイト)です。
注)New世代領域の大きさには、「to space」領域の大きさが含まれません。
（GC処理はNew世代領域を「eden space」、「from space」および「to space」の3つの内部領域に細分割して制御しています。）
Old世代領域の識別名を示します。
使用されているGC処理の違いにより、以下の識別名が出力されます。
Tenured: シリアルGCの場合
ParOldGen: パラレルGCの場合
CMS: CMS付きパラレルGCの場合
GC処理実行前のOld世代領域に存在したオブジェクトの総量(バイト)です。
GC処理実行後のOld世代領域に存在するオブジェクトの総量(バイト)です。
Old世代領域の大きさ(バイト)です。
GC処理実行前のメモリ割り当てプールに存在したオブジェクトの総量(バイト)です。
$5+$9の値です。
GC処理実行後のメモリ割り当てプールに存在するオブジェクトの総量(バイト)です。
$6+$10の値です。
メモリ割り当てプールの大きさ(バイト)です。
$7+$11の値です。
注)メモリ割り当てプールの大きさには、New世代領域の「to space」領域の大きさが含まれません。
（GC処理はNew世代領域を「eden space」、「from space」および「to space」の3つの内部領域に細分割して制御しています。）
メタスペースの識別名です。
使用されているGC処理の違いに関わらず、以下の識別名が出力されます。
Metaspace
GC処理実行前のメタスペースに存在したオブジェクトの総量(バイト)です。
GC処理実行後のメタスペースに存在するオブジェクトの総量(バイト)です
メタスペースの大きさ(バイト)です。
GC処理実行に要した時間(秒)です。
$19aは、$4の世代領域のGC処理に要した実行(秒)です。
$19bは、$8の世代領域のGC処理に要した実行(秒)です。
パラレルGCの場合、$19a、$19bは表示されません。
注)GC処理は、Javaアプリケーションとしての動作を停止させて実行されます。
GC処理期間中に、GC処理が使用したCPU時間（秒）です。
GC処理期間中に、システム（ＯＳ）が使用したCPU時間（秒）です。
GC処理にかかった実時間（秒）です。
注意
ログ出力量の増加
本オプションの指定により、ログ出力が増大します。
本オプションを指定する場合は、ログ出力量についての注意が必要です。
参考
$2、$3、$12、$13、$14、および$19に対する出力情報は、GC処理の結果ログ出力機能として“-verbose:gc”オプションだけを指定した際に出力される情報と対応します。
注意
マイナーGCの場合、基本的にはOld世代領域の情報[$8: $9->$10($11), $19b secs]および、メタスペースの情報[$15 : $16->$17($18)]は出力されません。但し、マイナーGCの発動を経由してFullGCが処理される場合があります。その場合、$2（GC種別）がマイナーGCの名称となっていますが、FullGCも追加されたフォーマットとなります。フォーマットがマイナーGCか、FullGCも追加されたものかは、$4または$8のGC対象の領域名から判断することができます。
シリアルGC、および、CMS付きパラレルGCの場合、FullGCのログに、New世代領域のログ"$1a: [$4: $5->$6($7), $19a secs]"が出力されない場合があります。
$4は、New世代領域の識別名を指しますが、識別名の後にGCの発生した理由が付加される場合があります。
マイナーGCおよびFull GCの延長で、CMS-GC処理が動作した場合は、上記の「GC処理の結果ログとして出力される情報の拡張形式」にならない場合があります。
-XX:+PrintGCDetailsの出力には、ガーベジコレクション処理の結果ログの他に、警告やインフォメーションが出力される場合があります。
ログの見方
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秒である。
