verbose:gc 情報の使用 (AIX、Linux のみ)

-verbose:gcオプションを-Xgc:verboseGCCycleTime=Nオプションとともに使用すると、Metronomeガーベッジ・コレクター・アクティビティーに関する情報をコンソールに書き込むことができます。標準JVMからの-verbose:gc出力に含まれるすべてのXMLプロパティが、メトロノーム・ガーベッジ・コレクターの出力に作成または適用されるわけではありません。

ヒープ内の最小フリー・スペース、最大フリー・スペース、および平均フリー・スペースを表示するには、-verbose:gcオプションを使用します。これにより、ヒープのアクティビティーや使用状況のレベルを確認し、必要に応じて値を調整することができます。 -verbose:gcオプションは、Metronome統計をコンソールに書き込みます。

-Xgc:verboseGCCycleTime=Nオプションは、情報の取得頻度を制御します。このオプションにより、ミリ秒単位の要約のダンプ時間が決まります。 N のデフォルト値は 1000 ミリ秒です。要約がダンプされるのは、サイクル・タイムに指定された時点ちょうどではなく、この時間の基準を満たす最後のガーベッジ・コレクション・イベント時です。これらの統計の収集および表示により、Metronome ガーベッジ・コレクターによる休止時間が増加する可能性があります。また、N の値が小さくなるほど、休止時間が長くなる可能性があります。

クォンタは、アプリケーションの中断時間または休止時間を生じさせる、Metronome ガーベッジ・コレクター・アクティビティーの単一期間です。

verbose:gc 出力の例

以下にアクセス:

java -Xgcpolicy:metronome -verbose:gc -Xgc:verboseGCCycleTime=N myApplication

ガーベッジ・コレクションが起動されると、trigger start イベントが発生し、その後に任意の数の heartbeat イベントが続き、起動の完了時に trigger end イベントが発生します。この例は、verbose:gc出力としてトリガーされたガーベッジ・コレクション・サイクルを示しています。

<trigger-start id="25" timestamp="2011-07-12T09:32:04.503" /> 

<cycle-start id="26" type="global" contextid="26" timestamp="2011-07-12T09:32:04.503" intervalms="984.285" /> 

<gc-op id="27" type="heartbeat" contextid="26" timestamp="2011-07-12T09:32:05.209">   
  <quanta quantumCount="321" quantumType="mark" minTimeMs="0.367" meanTimeMs="0.524" maxTimeMs="1.878" 
    maxTimestampMs="598704.070" />   
  <exclusiveaccess-info minTimeMs="0.006" meanTimeMs="0.062" maxTimeMs="0.147" />   
  <free-mem type="heap" minBytes="99143592" meanBytes="114374153" maxBytes="134182032" />   
  <thread-priority maxPriority="11" minPriority="11" />
</gc-op> 

<gc-op id="28" type="heartbeat" contextid="26" timestamp="2011-07-12T09:32:05.458">   
  <quanta quantumCount="115" quantumType="sweep" minTimeMs="0.430" meanTimeMs="0.471" maxTimeMs="0.511" 
    maxTimestampMs="599475.654" />   
  <exclusiveaccess-info minTimeMs="0.007" meanTimeMs="0.067" maxTimeMs="0.173" />   
  <classunload-info classloadersunloaded=9 classesunloaded=156  />     
  <references type="weak" cleared="660" />   
  <free-mem type="heap" minBytes="24281568" meanBytes="55456028" maxBytes="87231320" />   
  <thread-priority maxPriority="11" minPriority="11" />
</gc-op> 

<gc-op id="29" type="syncgc" timems="136.945" contextid="26" timestamp="2011-07-12T09:32:06.046">   
  <syncgc-info reason="out of memory" exclusiveaccessTimeMs="0.006" threadPriority="11" />   
  <free-mem-delta type="heap" bytesBefore="21290752" bytesAfter="171963656" />
</gc-op> 

<cycle-end id="30" type="global" contextid="26" timestamp="2011-07-12T09:32:06.046" /> 

<trigger-end id="31" timestamp="2011-07-12T09:32:06.046" />

発生する可能性のあるイベントのタイプは以下のとおりです。

< トリガー開始 ...>: 使用メモリー量がトリガーしきい値を上回ったことによる、ガーベッジ・コレクション・サイクルの開始。デフォルトのしきい値はヒープの 50% です。 intervalms属性は、前のtrigger endイベント（id-1付き）から今回のtrigger startイベントまでの間隔である。
< トリガー終了 ...>: ガーベッジ・コレクション・サイクルにより、使用済みメモリー量がトリガーしきい値未満まで下がりました。ガーベッジ・コレクション・サイクルが終了しても、使用済みメモリーがトリガーしきい値を下回らなかった場合は、新しいガーベッジ・コレクション・サイクルが、同じコンテキスト ID で開始されます。 trigger startイベントごとに、同じコンテキスト ID を持つ一致するtrigger endイベントがあります。 intervalms属性は、前のtrigger startイベントと現在のtrigger endイベントの間の間隔です。この間に、使用済みメモリーがトリガーしきい値を下回るまで、1 つ以上のガーベッジ・コレクション・サイクルが完了します。
< gc-op id="28 "type="heartbeat" ...>: 対象となる期間中のすべてのガーベッジ・コレクション・クォンタに関する (メモリーや時間などの) 情報を収集する定期的なイベント。ハートビート・イベントは、一致するtrigger startイベントとtrigger endイベントのペアの間でのみ発生します。つまり、アクティブなガーベッジ・コレクション・サイクルが進行中です。 intervalms属性は、直前のハートビート・イベント（id-1を使用）とこのハートビート・イベントの間の間隔です。
< gc-op id="29 "タイプ = "syncgc" ...>: 同期 (非決定論的な) ガーベッジ・コレクション・イベント。同期ガーベッジ・コレクションを参照してください。

この例の各 XML タグの意味は以下のとおりです。

< クアンタ ...>: ハートビート間隔内のクォンタ休止時間の長さの要約。休止時間の長さがミリ秒で示されます。
< フリー・メモリー・タイプ =「ヒープ」...>: ハートビート間隔でのフリー・ヒープ・スペース量 (各ガーベッジ・コレクション・クォンタの終了時にサンプリングされます) の要約。
<classunload-info classloadersunloaded=9 classesunloaded=156 />: ハートビート間隔においてアンロードされたクラスおよびクラス・ローダーの数。
< は type="weak " cleared="660 /> を参照します。: ハートビート間隔中にクリアされた Java™ 参照オブジェクトの数とタイプ。

注:

2 つのハートビートの間にガーベッジ・コレクション・クォンタが 1 回しか生じなかった場合、空きメモリーのサンプリングは、この 1 回のクォンタの終了時にのみ行われます。このため、ハートビートの要約で示される最小量、最大量、および平均量はすべて同じになります。
ガーベッジ・コレクション・アクティビティーが必要になるほどヒープが埋まっていない場合、2 つのハートビート・イベントの間隔は、指定されたサイクル・タイムよりも大幅に長くなる可能性があります。例えば、ご使用のプログラムでガーベッジ・コレクション・アクティビティーを数秒ごとに一度だけ行う必要がある場合、ハートビートは数秒ごとに一度だけになると考えられます。
ガーベッジ・コレクション・アクティビティーに必要なヒープが十分でない場合、2 つのハートビート・イベントの間隔が指定されたサイクル・タイムより大幅に長くなる可能性があります。例えば、ご使用のプログラムでガーベッジ・コレクション・アクティビティーを数秒ごとに一度だけ行う必要がある場合、ハートビートは数秒ごとに一度だけになると考えられます。
同期ガーベッジ・コレクションや優先順位変更などのイベントが発生した場合、そのイベントおよび保留中の (ハートビートなどの) すべてのイベントの詳細は、直ちに出力として生成されます。
指定された期間の最大ガーベッジ・コレクション・クォンタが大きすぎる場合は、-Xgc:targetUtilizationオプションを使用してターゲットの使用率を減らすことができます。このアクションは、ガーベッジ・コレクターの処理時間を増やします。あるいは、-Xmxオプションを使用してヒープ・サイズを増やすこともできます。同様に、ご使用のアプリケーションで、現在報告されている時間よりも長い遅延時間が許容されている場合は、ターゲットの使用率を増やすか、ヒープ・サイズを減らすことができます。
出力は、-Xverbosegclog:<file>オプションを使用して、コンソールではなくログ・ファイルにリダイレクトできます。例えば、-Xverbosegclog:outと指定すると、-verbose:gc出力がファイルアウトに書き込まれます。
thread-priority にリストされている優先順位は、基礎となるオペレーティング・システムのスレッド優先順位であり、Java スレッド優先順位ではありません。

同期ガーベッジ・コレクション

同期（非決定的）ガーベッジ・コレクションが発生した場合も、エントリーが-verbose:gcログに書き込まれます。このイベントの原因として、以下の 3 つが考えられます。

コード内の明示的なSystem.gc()呼び出しです。
JVM でメモリー不足が発生し、OutOfMemoryError 状態を回避するために、同期ガーベッジ・コレクションが実行された。
JVM が継続的なガーベッジ・コレクション中にシャットダウンした。 JVM はガーベッジ・コレクションを取り消すことができないため、ガーベッジ・コレクションを同期的に完了し、終了します。

System.gc()項目の例を以下に示します。

<gc-op id="9" type="syncgc" timems="12.92" contextid="8" timestamp=
"2011-07-12T09:41:40.808">
  <syncgc-info reason="system GC" totalBytesRequested="260" exclusiveaccessTimeMs="0.009" 
  threadPriority="11" />
  <free-mem-delta type="heap" bytesBefore="22085440" bytesAfter="136023450" />
  <classunload-info classloadersunloaded="54" classesunloaded="234" />
  <references type="soft" cleared="21" dynamicThreshold="29" maxThreshold="32" />
  <references type="weak" cleared="523" />
  <finalization enqueued="124" />
</gc-op>

JVM のシャットダウンの結果として行われた同期ガーベッジ・コレクションの項目は、以下の例のようになります。

<gc-op id="24" type="syncgc" timems="6.439" contextid="19" timestamp="2011-07-12T09:43:14.524">   
  <syncgc-info reason="VM shut down" exclusiveaccessTimeMs="0.009" threadPriority="11" />   
  <free-mem-delta type="heap" bytesBefore="56182430" bytesAfter="151356238" />   
  <classunload-info classloadersunloaded="14" classesunloaded="276" />   
  <references type="soft" cleared="154" dynamicThreshold="29" maxThreshold="32" /> 
  <references type="weak" cleared="53" />   
  <finalization enqueued="34" />
</gc-op>

この例の XML タグおよび属性の意味は以下のとおりです。

<gc-op id="9" type="syncgc" timems="6.439" ...: この行は、イベント・タイプが同期ガーベッジ・コレクションであることを示しています。 timems属性は、同期ガーベッジ・コレクションの所要時間（ミリ秒）です。
< syncgc-info 理由 = "..." />: 同期ガーベッジ・コレクションの原因を示しています。
< フリー・メモリー・デルタ ... />: 同期ガーベッジ・コレクションの前後の空き Java ヒープ・メモリー (バイト単位)。
< ファイナライズ ... />: ファイナライズを待っているオブジェクトの数。
< classunload-情報 ... />: ハートビート間隔においてアンロードされたクラスおよびクラス・ローダーの数。
< references type="weak " cleared="53" .../> を参照します。: ハートビート間隔中にクリアされた Java 参照オブジェクトの数とタイプ。

メモリー不足状態または VM のシャットダウンが原因の同期ガーベッジ・コレクションは、ガーベッジ・コレクターがアクティブである場合にのみ発生する可能性があります。即時というわけではありませんが、trigger start イベントが先行する必要があります。場合によっては、複数の heartbeat イベントが、trigger start イベントと synchgc イベントの間に発生する可能性があります。 System.gc()によって引き起こされる同期ガーベッジ・コレクションは、いつでも発生する可能性があります。

すべての GC クォンタのトラッキング

個々のGCクアンタは、GlobalGCStartおよびGlobalGCEndトレース・ポイントを有効にすることで追跡できます。これらのトレース・ポイントは、同期ガーベッジ・コレクションを含む、すべての Metronome ガーベッジ・コレクター・アクティビティーの開始時と終了時に生成されます。これらのトレース・ポイントの出力は以下のようになります。

03:44:35.281 0x833cd00 j9mm.52 - GlobalGC start: globalcount=3

03:44:35.284 0x833cd00 j9mm.91 - GlobalGC end: workstackoverflow=0 overflowcount=0

メモリー不足に関する項目

ヒープがフリー・スペースを使い尽くした場合、 OutOfMemoryError 例外がスローされる前に、エントリーが -verbose:gc ログに書き込まれます。この出力は以下の例のようになります。

<out-of-memory id="71" timestamp="2011-07-12T10:21:50.135" memorySpaceName="Metronome" 
  memorySpaceAddress="0806DFDC"/>

デフォルトでは、OutOfMemoryError 例外の結果として、Javadump が生成されます。このダンプには、プログラムによって使用されたメモリーに関する情報が含まれます。

NULL
1STSEGTOTAL    Total memory:           4066080 (0x003E0B20)
1STSEGINUSE    Total memory in use:    3919440 (0x003BCE50)
1STSEGFREE     Total memory free:       146640 (0x00023CD0)