-Xtgc トレース

1つ以上のTGC（トレースガベージコレクタ）トレースを有効にすることで、-verbose:gcオプションを使用した場合よりもさらに詳細なガベージコレクション情報を取得することができます。

このセクションでは、使用可能なさまざまな-Xtgcトレースを要約します。この出力は STDOUT に書き込まれます。 -Xtgc:backtrace,compactionのようにカンマで区切って複数のトレースを同時に有効にすることができます。

xtgc-backtrace
xtgc-compaction
xtgc-concurrent
xtgc-dump
xtgc-excessivegc
xtgc-freelist
xtgc-parallel
xtgc-scavenger
xtgc-terse

-Xtgc オプションを参照してください。

-Xtgc:backtrace

このトレースは、ガーベッジ・コレクションを開始させたスレッドを追跡する情報を表示します。

System.gc() の場合は、例えば次のような情報が表示されます。

"main" (0x0003691C)

これは、「メイン」という名前のスレッドとosThread0x0003691CによってGCがトリガーされたことを示しています。

それぞれのグローバル・コレクションまたはスカベンジャー・コレクションについて 1 行が表示されて、そのガーベッジ・コレクションを開始させたスレッドが示されます。

-Xtgc:compaction

このトレースは、圧縮に関する情報を表示します。

このトレースの例を次に示します。

Compact(3): reason = 7 (forced compaction)
Compact(3): Thread 0, setup stage: 8 ms.
Compact(3): Thread 0, move stage: handled 42842 objects in 13 ms, bytes moved 2258028.
Compact(3): Thread 0, fixup stage: handled 0 objects in 0 ms, root fixup time 1 ms.
Compact(3): Thread 1, setup stage: 0 ms.
Compact(3): Thread 1, move stage: handled 35011 objects in 8 ms, bytes moved 2178352.
Compact(3): Thread 1, fixup stage: handled 74246 objects in 13 ms, root fixup time 0 ms.
Compact(3): Thread 2, setup stage: 0 ms.
Compact(3): Thread 2, move stage: handled 44795 objects in 32 ms, bytes moved 2324172.
Compact(3): Thread 2, fixup stage: handled 6099 objects in 1 ms, root fixup time 0 ms.
Compact(3): Thread 3, setup stage: 8 ms.
Compact(3): Thread 3, move stage: handled 0 objects in 0 ms, bytes moved 0.
Compact(3): Thread 3, fixup stage: handled 44797 objects in 7 ms, root fixup time 0 ms.

このトレースは、3 回目のグローバル・ガーベッジ・コレクション中に「7」という理由のために圧縮が実行されたことを示しています。この例では、4 つのスレッドが圧縮を実行しています。このトレースは、セットアップ時、移動時、および修正時に各スレッドによって実行された処理を示しています。各スレッドによって処理されたオブジェクトの数とともに、各ステージの時間が表示されています。

-Xtgc:concurrent

このトレースは、並行マーク・ヘルパー・スレッドに関する基本的な追加情報を表示します。

注: このオプションは、 -Xgcpolicy:balanced オプションと一緒に使用することはできません。これらの 2 つのオプションを一緒に使用しようとすると、JVM は開始しません。

<CONCURRENT GC BK thread 0x0002645F activated after GC(5)>

<CONCURRENT GC BK thread 0x0002645F (started after GC(5)) traced 25435>

このトレースは、バックグラウンド・スレッドがアクティブ化されたタイミング、および実行されたトレースの量 (バイト単位) を示しています。

-Xtgc:dump

このトレースは、グローバル・ガーベッジ・コレクションのスイープ・フェーズの後に追加情報を表示します。

これは非常に大きなトレースであり、1 回のガーベッジ・コレクションの出力例です。

<GC(4) 13F9FE44 freelen=x000002C4 -- x00000038 spec/jbb/Stock>
<GC(4) 13FA0140 freelen=x00000010>
<GC(4) 13FA0150 freelen=x00000050 -- x0000001C java/lang/String>
<GC(4) 13FA0410 freelen=x000002C4 -- x00000024 spec/jbb/infra/Collections/
     longBTreeNode>
<GC(4) 13FA0788 freelen=x00000004 -- x00000050 java/lang/Object[]>
<GC(4) 13FA0864 freelen=x00000010>
<GC(4) 13FA0874 freelen=x0000005C -- x0000001C java/lang/String>
<GC(4) 13FA0B4C freelen=x000002C4 -- x00000038 spec/jbb/Stock>
<GC(4) 13FA0E48 freelen=x00000010>
<GC(4) 13FA0E58 freelen=x00000068 -- x0000001C java/lang/String>
<GC(4) 13FA1148 freelen=x000002C4 -- x00000038 spec/jbb/Stock>
<GC(4) 13FA1444 freelen=x00000010>
<GC(4) 13FA1454 freelen=x0000006C -- x0000001C java/lang/String>
<GC(4) 13FA174C freelen=x000002C4 -- x00000038 spec/jbb/Stock>
<GC(4) 13FA1A48 freelen=x00000010>
<GC(4) 13FA1A58 freelen=x00000054 -- x0000001C java/lang/String>
<GC(4) 13FA1D20 freelen=x000002C4 -- x00000038 spec/jbb/Stock>
<GC(4) 13FA201C freelen=x00000010>
<GC(4) 13FA202C freelen=x00000044 -- x0000001C java/lang/String>
<GC(4) 13FA22D4 freelen=x000002C4 -- x00000038 spec/jbb/Stock>
<GC(4) 13FA25D0 freelen=x00000010>
<GC(4) 13FA25E0 freelen=x00000048 -- x0000001C java/lang/String>
<GC(4) 13FA2890 freelen=x000002C4 -- x00000038 spec/jbb/Stock>
<GC(4) 13FA2B8C freelen=x00000010>
<GC(4) 13FA2B9C freelen=x00000068 -- x0000001C java/lang/String>
<GC(4) 13FA2E8C freelen=x000002C4 -- x00000038 spec/jbb/Stock>
<GC(4) 13FA3188 freelen=x00000010>

システム内の空きチャンクごとに 1 行が出力されます。これには、何らかの理由 (通常は小さすぎること) によりフリー・リストに含まれていない空きチャンクであるダーク・マターも含まれます。各行には、そのチャンクの基底アドレスとバイト単位サイズが表示されます。ヒープ内でそのチャンクの後ろにオブジェクトが存在する場合は、そのオブジェクトのサイズとクラス名も表示されます。

-Xtgc:excessiveGC

このトレースは、ガーベッジ・コレクション・サイクルに関する統計情報を表示します。

ガーベッジ・コレクション・サイクルが完了したら、次のようなトレース・エントリーが作成されます。

excessiveGC: gcid="10" intimems="122.269" outtimems="1.721" \
             percent="98.61" averagepercent="37.89"

このトレースは、ガーベッジ・コレクションの実行にかかった時間と、ガーベッジ・コレクションが実行されないまま経過した時間の長さを示しています。この例では、ガーベッジ・コレクション・サイクル 10 が完了するのに 122.269 ミリ秒かかり、コレクション 9 と 10 の間に 1.721 ミリ秒が経過しました。これらの統計情報は、コレクション 9 の終了時からコレクション 10 の終了時までの時間のうち、ガーベッジ・コレクションに費やされた時間が 98.61% を占めることを示しています。ガーベッジ・コレクションに費やされた時間の平均比率は 37.89% です。

ガーベッジ・コレクションに費やされた時間の平均比率が 95% に達すると、次のような追加のトレース・エントリーが作成されます。

excessiveGC: gcid="65" percentreclaimed="1.70" freedelta="285728" \
             activesize="16777216" currentsize="16777216" maxiumumsize="16777216"

このトレースは、回収されたガーベッジの量を示しています。この例では、ガーベッジ・コレクション 65 によって 285728 バイト分の記憶域が解放され、これは合計ヒープ・サイズの 1.7% に相当します。この例では、ヒープが最大サイズまで拡張されたことも示しています（-Xmxを参照）。

ガーベッジ・コレクションに費やされた時間の平均比率が 95% に達して、ガーベッジ・コレクションによって解放された空きスペースの比率が 3% を下回ると、次のような追加のトレース・エントリーが作成されます。

excessiveGC: gcid="65" percentreclaimed="1.70" minimum="3.00" excessive gc raised

この場合は JVM によって OutOfMemoryError がスローされます。

-Xtgc:freelist

このトレースは、ガーベッジ・コレクションの実行前に、フリー・リストに関する情報と、前回のガーベッジ・コレクション以降の割り振りに関する統計情報を出力します。

このトレースは、フリー・リスト上のアイテムの数を出力します。これには「据え置き」エントリーも含まれます (スカベンジャーでは、使用されていないセミスペースは据え置きフリー・リスト・エントリーです)。 TLH 割り振りと非 TLH 割り振りについては、このトレースでは合計割り振り数、平均割り振りサイズ、および割り振り時に破棄された合計バイト数が出力されます。非 TLH 割り振りについては、十分な大きさの項目が検出されるまでに検索された項目の平均数も表示されます。

 *8* free         0
  *8* deferred     0
total                0
<Alloc TLH: count 3588, size 3107, discard 31>
<  non-TLH: count 6219, search 0, size 183, discard 0>

-Xtgc:parallel

このトレースは、グローバル・ガーベッジ・コレクションのマーク・フェーズおよびスイープ・フェーズでの並列スレッドのアクティビティーに関する統計を表示します。

Mark:   busy  stall  tail   acquire   release
   0:      30    30     0        0         3
   1:      53     7     0       91        94
   2:      29    31     0       37        37
   3:      37    24     0      243       237
Sweep:  busy   idle sections 127  merge 0
   0:      10     0    96
   1:       8     1     0
   2:       8     1    31
   3:       8     1     0

このトレースには、4 つのスレッド (0-3)、およびガーベッジ・コレクションのマーク・フェーズおよびスイープ・フェーズで各スレッドが実行した作業が示されています。

ガーベッジ・コレクションのマーク・フェーズでは、「busy」、「stall」、および「tail」の各状態で経過した時間が (ミリ秒単位で) 示されています。マーク・フェーズで各スレッドが獲得および解放した作業パケットの数も示されています。

ガーベッジ・コレクションのスイープ・フェーズでは、「busy」および「idle」の状態で経過した時間が (ミリ秒単位で) 示されています。各スレッドが処理したスイープ・チャンクの数も、総計 (127) とともに示されています。合計マージ時間 (0 ミリ秒) も示されています。

-Xtgc:scavenger

このトレースは、それぞれのスカベンジャー・コレクションの後にヒストグラムを出力します。

サバイバー・スペースに残っているオブジェクトの各種クラスのグラフに加えて、各クラスの出現数と各オブジェクトのエージ (フリップされた回数) が表示されます。 1 回のスカベンジの出力例を次に示します。

{SCAV: tgcScavenger OBJECT HISTOGRAM}

{SCAV: | class | instances of age 0-14 in semi-space |
{SCAV: java/lang/ref/SoftReference 0 3 0 0 0 0 0 0 0 0 0 0 0 0 0
{SCAV: java/io/FileOutputStream 0 2 0 0 0 0 0 0 0 0 0 0 0 0 0
{SCAV: sun/nio/cs/StreamEncoder$ConverterSE 0 4 0 0 0 0 0 0 0 0 0 0 0 0 0
{SCAV: java/io/FileInputStream 0 1 0 0 0 0 0 0 0 0 0 0 0 0 0
{SCAV: char[][] 0 102 0 0 0 0 0 0 0 0 0 0 0 0 0
{SCAV: java/lang/ref/SoftReference[] 0 2 0 0 0 0 0 0 0 0 0 0 0 0 0
{SCAV: java/io/BufferedOutputStream 0 2 0 0 0 0 0 0 0 0 0 0 0 0 0
{SCAV: java/io/BufferedWriter 0 4 0 0 0 0 0 0 0 0 0 0 0 0 0
{SCAV: java/io/OutputStreamWriter 0 4 0 0 0 0 0 0 0 0 0 0 0 0 0
{SCAV: java/io/PrintStream 0 2 0 0 0 0 0 0 0 0 0 0 0 0 0
{SCAV: java/io/BufferedInputStream 0 1 0 0 0 0 0 0 0 0 0 0 0 0 0
{SCAV: java/lang/Thread[] 0 2 0 0 0 0 0 0 0 0 0 0 0 0 0
{SCAV: java/lang/ThreadGroup[] 0 2 0 0 0 0 0 0 0 0 0 0 0 0 0
{SCAV: sun/io/ByteToCharCp1252 0 1 0 0 0 0 0 0 0 0 0 0 0 0 0
{SCAV: sun/io/CharToByteCp1252 0 1 0 0 0 0 0 0 0 0 0 0 0 0 0

-Xtgc:terse

このトレースは、ガーベッジ・コレクションの前と後にヒープ全体の内容をダンプします。

これは非常に大きいトレースです。ヒープ内のオブジェクトごとまたは空きチャンクごとに、1 行のトレース出力が生成されます。各行に表示される内容は、基底アドレス、「a」(割り振り済みオブジェクトの場合) または「f」(空きチャンクの場合)、チャンクのバイト単位サイズ、およびオブジェクトの場合はそのクラス名です。次に例を示します。

*DH(1)* 230AD778 a x0000001C java/lang/String
*DH(1)* 230AD794 a x00000048 char[]
*DH(1)* 230AD7DC a x00000018 java/lang/StringBuffer
*DH(1)* 230AD7F4 a x00000030 char[]
*DH(1)* 230AD824 a x00000054 char[]
*DH(1)* 230AD878 a x0000001C java/lang/String
*DH(1)* 230AD894 a x00000018 java/util/HashMapEntry
*DH(1)* 230AD8AC a x0000004C char[]
*DH(1)* 230AD8F8 a x0000001C java/lang/String
*DH(1)* 230AD914 a x0000004C char[]
*DH(1)* 230AD960 a x00000018 char[]
*DH(1)* 230AD978 a x0000001C java/lang/String
*DH(1)* 230AD994 a x00000018 char[]
*DH(1)* 230AD9AC a x00000018 java/lang/StringBuffer
*DH(1)* 230AD9C4 a x00000030 char[]
*DH(1)* 230AD9F4 a x00000054 char[]
*DH(1)* 230ADA48 a x0000001C java/lang/String
*DH(1)* 230ADA64 a x00000018 java/util/HashMapEntry
*DH(1)* 230ADA7C a x00000050 char[]
*DH(1)* 230ADACC a x0000001C java/lang/String
*DH(1)* 230ADAE8 a x00000050 char[]
*DH(1)* 230ADB38 a x00000018 char[]
*DH(1)* 230ADB50 a x0000001C java/lang/String
*DH(1)* 230ADB6C a x00000018 char[]
*DH(1)* 230ADB84 a x00000018 java/lang/StringBuffer
*DH(1)* 230ADB9C a x00000030 char[]
*DH(1)* 230ADBCC a x00000054 char[]
*DH(1)* 230ADC20 a x0000001C java/lang/String
*DH(1)* 230ADC3C a x00000018 java/util/HashMapEntry
*DH(1)* 230ADC54 a x0000004C char[]