ページの先頭行へ戻る
Interstage Application Server/Interstage Web Server Express チューニングガイド
FUJITSU Software
第8章 JDK/JREのチューニング > 8.2 ガーベジコレクション(GC) > 8.2.6 ガーベジコレクションのログ出力
前次

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

  ガーベジコレクション(GC)のログを採取する場合は、図1のオプションを指定します。本オプションの指定により、GCが発生するたびに、GC処理の結果ログが標準出力へ1行ずつ出力されます。

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

-verbose:gc

出力フォーマットを図2、出力例を図3に示します。

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

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

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

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

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

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

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

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

図3 GCログの出力例

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

  なおFJVMでは、GC処理の結果ログ出力機能の強化を行っています。
  より詳細なGC処理の結果ログ情報を得る場合には、当該機能を使用してください。詳細は、“8.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 アンロードされたクラス名]”を結果ログ出力の途中に挿入したい場合は、図4のオプションを指定してください。

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

-XX:+ClassUnloadingInfo

GC処理結果ログの格納先ファイルの指定

  図5のオプションを指定すると、GC処理の結果ログおよびクラスのインスタンス情報を、標準出力ではなく、指定したファイルへ出力先を切り換えることができます。

  なお、Interstage Application Server配下でJavaアプリケーションを実行する際に図5のオプションを指定した場合、以下の問題が発生します。

  そのため、Interstage Application Server配下でJavaアプリケーションを実行する場合には、図5のオプションを指定しないでください。

  図5のオプションは、Interstage Application Serverとは関係しない単独のJavaアプリケーションを実行する場合に、必要に応じて指定してください。

図5 GC処理の結果ログの格納先ファイルを指定するオプション

-Xloggc:GC処理の結果ログの格納先ファイル名

注1) このオプションを指定すると、自動的に“-verbose:gc”オプションも指定したと見做されます。そのため、“-verbose:gc”オプションの指定がない場合でも、GC処理の結果ログが出力され、また、ガーベジコレクション処理の結果ログ出力機能の強化を使用することもできます。

なお、“-Xloggc”オプション指定により出力されたGC処理の結果ログの先頭には、「Java VMが起動されてからの経過時間(秒)」が「GC処理の実行開始時間」として自動的に付加されます（以下の形式で出力されます）。

GC処理の実行開始時間: GC処理の結果ログ(図2の出力フォーマットと同じ)

「GC処理の実行開始時間」のフォーマットは変更できません。

（ガーベジコレクション処理の結果ログ出力機能の強化も使用して出力されたGC処理の結果ログの場合は、「GC処理の実行開始時間」のフォーマットを、ログ出力における「8.5.7 ログ出力における時間情報のフォーマット指定機能」により指定できます。）

注2) 格納先ファイル名の指定には、絶対パスや相対パスのディレクトリ名を付加した形式も可能です。

注3) 格納先ファイル名の中にあるディレクトリが存在しないなど、何らかの理由で指定された格納先ファイルにアクセスできなかった場合、GC処理の結果ログは出力されません。

8.2.6.1 ガーベジコレクション処理の結果ログ出力機能の強化

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

  “-verbose:gc”オプションを指定してGC処理の結果ログを出力する際、図1のオプションを追加指定することにより、GC処理の結果ログとして出力される情報が、図2から図5に示す形式に拡張されます。また、図6から図8に出力例を示します。

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

-XX:+UseFJverbose

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

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

  図2の各要素について、以下で説明します。

$1: GC処理の実行開始時間(ログ出力時の時間)

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

$2: GC種別

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

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

New世代領域の識別名を示します。
使用されている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処理の違いにより、以下の識別名が出力されます。

$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処理の違いにより、以下の識別名が出力されます。

$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”オプションだけを指定した際に出力される情報と対応します。

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

$1: CMS start

  図3の各要素について、以下で説明します。

$1: CMS-GC処理の実行開始時間(ログ出力時の時間)

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

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

$1: CMS stop-req

  図4の各要素について、以下で説明します。

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

Full GC要求発生時にCMS-GC処理が実行中であった場合、CMS-GC処理の終了要求時点(ログ出力時の時間)を示します。
ログ出力時の時間のフォーマットは、ログ出力における「8.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アプリケーション動作の実際の停止期間となります。

図5 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

  図5の各要素について、以下で説明します。

$1: CMS-GC処理の実行終了時間(ログ出力時の時間)

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

$2: 終了コード

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

$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処理が以下の場合です。

ログ出力量の増加

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

ログの見方

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

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

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

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

図7 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

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

図8 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]

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

前次
Copyright 2002-2014 FUJITSU LIMITED