|
|
-Xverbose コマンド ライン オプションは、Oracle JRockit JVM からの冗長出力を可能にします。これらの冗長出力を使用して、監視、チューニングおよび診断を行うことができます。この章では、いくつかの最も役に立つ冗長モジュールとそれらの出力の解釈方法について説明します。
| 注意 : | 出力は、JVM のバージョン間で異なる可能性があります。また、正確な形式は、任意の時点で変更される場合があります。 |
JRockit JVM で使用可能な冗長モジュールの多くは、メモリ管理およびガベージ コレクションのためのものです。表 19-1 に、この節で説明する冗長モジュールを示します。
ほとんどの冗長モジュールが、複数のログ レベルで使用できます。この節では、全般的なチューニングおよび監視に最も役立つ、デフォルトの (info) ログ レベルについてのみ説明します。
-Xverbose:memory (または -Xverbose:gc) モジュールは、ガベージ コレクション イベントに関する基本的な情報を提供します。このモジュールのオーバーヘッドは非常に低く、これは、プロダクション環境でもこのモジュールを有効にできることを意味しています。
JVM の起動時に、memory ログ モジュールは、メモリ管理システムのコンフィグレーションに関する基本的な数値をいくつか出力し、ガベージ コレクションの出力の読み方を示します。
コード リスト 19-1 は、memory ログ モジュールからの出力の冒頭部分の例を示しています。この例は、JRockit JVM R27.4 からのものです。行数を追加しています。
1: [memory ] GC mode: Garbage collection optimized for throughput, initial strategy: Generational Parallel Mark & Sweep
2: [memory ] heap size: 307200K, maximal heap size: 307200K, nursery size: 153600K
3: [memory ] <s>-<end>: GC <before>K-><after>K (<heap>K), <pause> ms
4: [memory ] <s/start> - start time of collection (seconds since jvm start)
5: [memory ] <end> - end time of collection (seconds since jvm start)
6: [memory ] <before> - memory used by objects before collection (KB)
7: [memory ] <after> - memory used by objects after collection (KB)
8: [memory ] <heap> - size of heap after collection (KB)
9: [memory ] <pause> - total sum of pauses during collection (milliseconds)
10: [memory ] run with -Xverbose:gcpause to see individual pauses
行 1 は、この実行で使用されたガベージ コレクション モードと、初期のガベージ コレクション方式について説明しています。
行 2 は、初期および最大ヒープ サイズと、初期ナーサリ サイズを示しています。
行 3 ～ 10 は、ガベージ コレクションの出力の形式について説明しています。
memory ログ モジュールは、ガベージ コレクションごとに 1 行を出力します。
コード リスト 19-2 は、memory ログ モジュールからの冗長出力の抜粋部分を示しています。この例は、JRockit JVM R27.4 からのものです。行数を追加しています。
1: [memory ] 83.976: parallel nursery GC 307200K->191044K (307200K), 35.584 ms
2: [memory ] 84.772-85.766: GC 288200K->73425K (307200K), 994.090 ms
3: [memory ] 87.036: parallel nursery GC 233783K->119655K (307200K), 57.716 ms
4: [memory ] 87.974: parallel nursery GC 233655K->119527K (307200K), 35.876 ms
ガベージ コレクションに関するそれぞれの出力は、タイムスタンプから始まります。これは、JVM が起動してからの時間 (秒) です。各行の末尾には、ヒープ サイズ (丸括弧内) と各ガベージ コレクションでのガベージ コレクション期間の合計も示されます。ガベージ コレクション期間には、休止およびコンカレント ガベージ コレクション フェーズの両方が含まれている場合があります。
行 1、3 および 4 は、若いコレクションからの出力です。行 1 の若いコレクションでは、占有されているヒープの量が 307200 KB から 191044 KB に削減されています。
行 2 は古いコレクションからの出力であり、占有されているヒープの量が 288200 KB から 73425 KB に削減されています。
ページ フォールトは、メモリ アクセスを遅くします。また、ガベージ コレクション中のページ フォールトにより、ガベージ コレクションにかかる時間が長くなる可能性があります。このため、冗長 memory ログ モジュールは、ガベージ コレクション中のページ フォールトの数がヒープ内のページ数の 5% を超えた場合に警告を出力します。
コード リスト 19-3 は、ページ フォールトの警告の例を示しています。この例は、JRockit JVM R27.4 からのものです。
[memory ] Warning: Your computer has generated 9435 page faults during the last garbage collection.
[memory ] If you find this swapping problematic, please consider running JRockit with a smaller heap.
-Xverbose:nursery ログ モジュールは、若いコレクションおよびナーサリのサイズ変更に関する詳細情報を提供します。この情報の一部は、JRockit JVM を監視およびチューニングするために役立ちます。オーバーヘッドは非常に低く、これは、プロダクション環境でもこのモジュールを有効にできることを意味しています。
nursery ログ モジュールは、JRockit JVM R27.2 以上のリリースで使用できます。
コード リスト 19-4 は、若いコレクション中の nursery ログ モジュールからの出力の例を示しています。この例は、JRockit JVM R27.4 からのものです。行数を追加しています。
1: [nursery] KeepAreaStart: 0x015FFFF0 KeepAreaEnd: 0x01AFFFF0
2: [nursery] Young collection 86 started. This YC is running while the OC is in phase: not running.
3: [nursery] Setting mmNurseryMarker[0] to 0x015FFFF0
4: [nursery] Setting mmNurseryMarker[1] to 0x01AFFFF0
行 1、3 および 4 には、保持領域のサイズおよび位置に関連する情報が含まれています。この情報は、高度な診断にのみ使用されます。
行 2 は、若いコレクションのシーケンス番号を示しています。また、これは、若いコレクションは実行されているが、古いコレクションは実行されていないことも示しています。その他の古いコレクションのフェーズには、マーキング、プレクリーニングおよびスイーピングがあります。これらはコンカレントな古いコレクションのコンカレント フェーズです。
一部のガベージ コレクションのモードおよび方式では、ランタイムにナーサリのサイズを調整してパフォーマンスを最適化します。nursery ログ モジュールは、ナーサリのサイズ調整の計算およびナーサリのサイズ変更に関する情報をいくつか示します。
コード リスト 19-5 は、古いコレクションからのナーサリのサイズ変更に関する出力の例を示しています。この例は、JRockit JVM R27.4 からのものです。行数を追加しています。
1: [nursery] Optimal nursery size: 157286400, free heap: 314572800
2: [nursery] Nursery size increased from 0kb to 153600kb. Parts: 4023
行 1 は、ヒューリスティックにより、最適なナーサリ サイズが 157286400 バイトであることが判明したことを示しています。ただし、メモリ管理システムで、厳密にこのサイズでナーサリを作成できない場合があります。
行 2 は、ナーサリ サイズが 0 (ナーサリなし) から 153600 KB に増加し、ナーサリが 4023 のチャンクで構成されていることを示しています。
-Xverbose:memdbg ログ モジュールは、ガベージ コレクションおよびメモリ管理に関する詳細情報を提供します。このログ モジュールを有効にすると、nursery ログ モジュールなどのその他の一部のログ モジュールも有効になります。この節では、memdbg に分類される出力についてのみ説明しており、その他のすべての冗長出力は、例から削除されています。
memdbg 冗長出力のオーバーヘッドは低いため、プロダクション環境で使用できます。
コード リスト 19-6 は、memdbg 冗長モジュールからの出力の冒頭部分の例を示しています。この例は、JRockit JVM R27.4 からのものです。行数を追加しています。
1: [memdbg ] Memory layout after heap allocation:
2: [memdbg ] ' ' - free, '-' - OS reserved range, 'r' - reserved, 'x' - committed,
3: [memdbg ] '+' - committed/read, 'e' - committed/executable
4: [memdbg ] 'J' - java heap, 'j' - java heap data structures
5: [memdbg ] 00 0.00Gb -eeJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJ
6: [memdbg ] 10 0.25Gb JJJJJJJJJJJJJJ
7: [memdbg ] 20 0.50Gb
8: [memdbg ] 30 0.75Gb
9: [memdbg ] 40 1.00Gb
10: [memdbg ] 50 1.25Gb
11: [memdbg ] 60 1.50Gb
12: [memdbg ] 70 1.75Gb e e - e e e ejj
13: [memdbg ] 80 2.00Gb ----------------------------------------------------------------
14: [memdbg ] 90 2.25Gb ----------------------------------------------------------------
15: [memdbg ] a0 2.50Gb ----------------------------------------------------------------
16: [memdbg ] b0 2.75Gb ----------------------------------------------------------------
17: [memdbg ] c0 3.00Gb ----------------------------------------------------------------
18: [memdbg ] d0 3.25Gb ----------------------------------------------------------------
19: [memdbg ] e0 3.50Gb ----------------------------------------------------------------
20: [memdbg ] f0 3.75Gb ----------------------------------------------------------------
21: [memdbg ] Minimum TLA size is 2048 bytes
22: [memdbg ] Preferred TLA size is 38912 bytes
23: [memdbg ] Large object limit is 2048 bytes
24: [memdbg ] Minimal blocksize on the freelist is 2048 bytes
25: [memdbg ] Initial and maximum number of gc threads: 2, of which 2 parallel threads, 1 concurrent threads, and 2 yc threads
26: [memdbg ] Prefetch distance in balanced tree: 4
27: [memdbg ] Using prefetch linesize: 32 bytes chunks: 512 bytes pf_dist: 64 bytes
行 1 ～ 20 は、Java ヒープが割り当てられた後の、マシンでのメモリ レイアウトについて説明しています。この情報は、ヒープの位置調整に関連する問題の診断に使用できます。
行 21 ～ 24 は、最小および推奨のスレッドローカル領域のサイズ、大きなオブジェクトの制限およびフリーリストでの最小ブロックサイズを示しています。これらの値は、ヒープ サイズやガベージ コレクタ、および JRockit JVM のバージョンによって異なる可能性があります。
行 25 は、ガベージ コレクション スレッドの数を示しています。
行 26 と 27 には、プリフェッチに関する情報が含まれています。これらは、主に高度な診断とチューニングに役立ちます。
memdbg モジュールは、ガベージ コレクションに関する出力に、多数の役に立つ情報を追加します。ほとんどのチューニングおよび診断において、この情報は不可欠です。出力はガベージ コレクションの種類によって異なります。
コード リスト 19-7 は、一世代のパラレルな古いコレクションからの memdbg 冗長出力の例を示しています。この例は、JRockit JVM R27.4 からのものです。行数を追加しています。
1: [memdbg ] GC reason: System.gc() called, cause: System.gc()
2: [memdbg ] Stopping of javathreads took 0.213 ms
3: [memdbg ] old collection 1 started
4: [memdbg ] Alloc Queue size before GC: 0, tlas: 0, oldest: 0
5: [memdbg ] Compacting 8 heap parts at index 120 (type external) (exceptional false)
6: [memdbg ] Starting parallel marking phase.
7: [memdbg ] Hard handles: Processed 1946 handles during normal processing.
8: [memdbg ] Weak handles: Processed 104 handles during normal processing.
9: [memdbg ] total mark time: 7.440 ms
10: [memdbg ] ending marking phase
11: [memdbg ] starting parallel sweeping phase
12: [memdbg ] total sweep time: 3.844 ms
13: [memdbg ] ending sweeping phase
14: [memdbg ] Alloc Queue size after GC: 0, tlas: 0, oldest: 0
15: [memdbg ] Page faults before GC: 6618, page faults after GC: 7938, pagesin heap: 76800
16: [memdbg ] Restarting of javathreads took 0.023 ms
行 1 には、ガベージ コレクションの原因が示されています。この例では、ガベージ コレクションは System.gc() 呼び出しによってトリガされました。
行 2 にはガベージ コレクションのためにすべての Java スレッドを停止するためにかかった時間が示されています。この場合は 0.213 ミリ秒です。この情報は、レイテンシの診断に役立ちます。
行 3 は、ガベージ コレクションのシーケンス番号を示しています。
行 4 には、ガベージ コレクションの開始時点でのオブジェクトの割り当てキューの状態に関する情報が含まれています。割り当てキューには、まだ処理されていないすべての保留中のオブジェクト割り当て要求が含まれます。この例では、割り当てキューは空です。これは、ガベージ コレクションが System.gc() によって開始された場合の通常の状態です。
行 5 は、このガベージ コレクションで計画されている圧縮を示しています。この例では、ヒープ パーツ 120 から 8 つのヒープ パーツが圧縮されます。圧縮の種類は外部であり、これは、オブジェクトが圧縮領域の外部に移動されることを意味します。また、圧縮は例外ではありません。つまり、圧縮ヒューリスティックが、圧縮の実行に時間がかかり過ぎると判断した場合は、圧縮は中止または中断される可能性があります。
行 7 および 8 は、弱ハンドルおよびハード ハンドルに関する情報を示しています。これは、主に高度な診断と監視に役立ちます。
行 9 は、マーク フェーズの合計時間を示しています。この時間には、休止およびコンカレント フェーズの両方が含まれる場合がありますが、この場合では、マーク フェーズ全体が、Java スレッドが休止している間に完了しています。
行 12 は、スイープ フェーズの合計時間を示しています。この時間には、休止およびコンカレント フェーズの両方が含まれる場合がありますが、この場合では、マーク フェーズ全体が、Java スレッドが休止している間に完了しています。
行 14 では、ガベージ コレクション後のオブジェクトの割り当てキューの状態に関する情報が示されています。この情報を行 4 の情報と比較して、オブジェクト割り当てが適切に実行されているかどうかを知ることができます。ガベージ コレクションの終了時点に割り当てキューに多数のオブジェクトがある場合は、重度の断片化などにより、オブジェクト割り当てが困難であることを示している可能性があります。
行 15 は、ガベージ コレクションの前と後のページ フォールトの統計値を示しています。ガベージ コレクション中のページ フォールトは、ガベージ コレクションの速度を大幅に低下させる可能性があります。
行 16 には、ガベージ コレクション後に、すべての Java スレッドを再開するためにかかった時間が示されています。この情報は、レイテンシの診断に役立ちます。
memdbg モジュールは、ガベージ コレクションに関する出力に、多数の役に立つ情報を追加します。ほとんどのチューニングおよび診断において、この情報は不可欠です。出力はガベージ コレクションの種類によって異なります。
コード リスト 19-8 は、一世代のモーストリ コンカレントな古いコレクションからの memdbg 冗長出力の例を示しています。この例は、JRockit JVM R27.4 からのものです。行数を追加しています。
1: [memdbg ] GC reason: GC trigger reached, cause: Heap too full
2: [memdbg ] Stopping of javathreads took 0.425 ms
3: [memdbg ] old collection 5 started
4: [memdbg ] Alloc Queue size before GC: 0, tlas: 0, oldest: 0
5: [memdbg ] Compacting 16 heap parts at index 112 (type internal) (exceptional false)
6: [memdbg ] Starting initial marking phase (OC1).
7: [memdbg ] Restarting of javathreads took 31.908 ms
8: [memdbg ] Starting concurrent marking phase (OC2).
9: [memdbg ] Hard handles: Processed 4251 handles during concurrent processing.
10: [memdbg ] Starting precleaning phase (OC3).
11: [memdbg ] Weak handles: Processed 146 handles during concurrent processing.
12: [memdbg ] Stopping of javathreads took 0.219 ms
13: [memdbg ] Starting final marking phase (OC4).
14: [memdbg ] Hard handles: Processed 8 handles during remaining processing.
15: [memdbg ] Weak handles: Processed 40 handles during remaining processing.
16: [memdbg ] total concurrent mark time: 512.526 ms
17: [memdbg ] ending marking phase
18: [memdbg ] starting concurrent sweeping phase
19: [memdbg ] total concurrent sweep time: 54.623 ms
20: [memdbg ] ending sweeping phase
21: [memdbg ] Alloc Queue size after GC: 0, tlas: 0, oldest: 0
22: [memdbg ] gc-trigger is 13.200 %
23: [memdbg ] Page faults before GC: 89592, page faults after GC: 92886, pages in heap: 76800
24: [memdbg ] Restarting of javathreads took 0.030 ms
行 1 には、ガベージ コレクションの原因が示されています。この例では、ヒープ占有率が、コンカレント ガベージ コレクションが開始される制限に達したためにガベージ コレクションが開始されました。
行 2 にはガベージ コレクションのためにすべての Java スレッドを停止するためにかかった時間が示されています。この場合は 0.425 ミリ秒です。同様の情報が、行 12 に示されています。この情報は、レイテンシの診断に役立ちます。
行 3 は、ガベージ コレクションのシーケンス番号を示しています。
行 4 には、ガベージ コレクションの開始時点でのオブジェクトの割り当てキューの状態に関する情報が含まれています。割り当てキューには、まだ処理されていないすべての保留中のオブジェクト割り当て要求が含まれます。この例では、割り当てキューは空です。
行 5 は、このガベージ コレクションで計画されている圧縮を示しています。この例では、ヒープ パーツ 112 から 16 のヒープ パーツが圧縮されます。圧縮の種類は内部であり、これは、オブジェクトが圧縮領域の内部で移動されることを意味します。また、圧縮は例外ではありません。つまり、圧縮ヒューリスティックが、圧縮の実行に時間がかかり過ぎると判断した場合は、圧縮は中止または中断される可能性があります。
行 7 には、コンカレント ガベージ コレクションのためにすべての Java スレッドを開始するのにかかった時間が示されています。同様の情報が、行 24 に示されています。
行 8 は、コンカレント マーク フェーズの開始をマークしています。
行 9、14 および 15 は、弱ハンドルおよびハード ハンドルに関する情報を示しています。これは、主に高度な診断と監視に役立ちます。
行 10 は、コンカレント プレクリーニング フェーズの開始をマークしています。
行 13 は、最終マーク フェーズの開始をマークしています。
行 16 は、マーク フェーズの合計時間を示しています。この時間には、休止およびコンカレント フェーズの両方が含まれます。
行 19 は、スイープ フェーズの合計時間を示しています。この時間には、休止およびコンカレント フェーズの両方が含まれます。
行 21 では、ガベージ コレクション後のオブジェクトの割り当てキューの状態に関する情報が示されています。この情報を行 4 の情報と比較して、オブジェクト割り当てが適切に実行されているかどうかを知ることができます。ガベージ コレクションの終了時点に割り当てキューに多数のオブジェクトがある場合は、重度の断片化などにより、オブジェクト割り当てが困難であることを示している可能性があります。
行 22 には、GC トリガの値が示されています。ヒープの空き領域がこの割合を下回ると、次のコンカレントな古いコレクションが開始されます。
行 23 は、ガベージ コレクションの前と後のページ フォールトの統計値を示しています。ガベージ コレクション中のページ フォールトは、ガベージ コレクションの速度を大幅に低下させる可能性があります。
コード リスト 19-9 は、若いコレクションからの memdbg 冗長出力の例を示しています。この例は、JRockit JVM R27.4 からのものです。行数を追加しています。
1: [memdbg ] GC reason: TLA allocation failed, cause: Get TLA From Nursery
2: [memdbg ] Stopping of javathreads took 0.198 ms
3: [memdbg ] Hard handles: Processed 4259 handles during normal processing.
4: [memdbg ] Weak handles: Processed 144 handles during normal processing.
5: [memdbg ] nursery GC 86: promoted 48984 objects (1718K) in 39.310 ms
6: [memdbg ] Page faults before GC: 89240, page faults after GC: 89754, pages in heap: 76800
7: [memdbg ] Nursery size after YC: 20971520
8: [memdbg ] Restarting of javathreads took 0.030 ms
行 1 には、ガベージ コレクションの原因が示されています。この例では、スレッド ローカル領域の割り当てが失敗したためにガベージ コレクションが開始されました。これは、若いコレクションが開始される通常の原因です。
行 2 にはガベージ コレクションのためにすべての Java スレッドを停止するのにかかった時間が示されています。この場合は 0.198 ミリ秒です。この情報は、レイテンシの診断に役立ちます。
行 3 および 4 は、弱ハンドルおよびハード ハンドルに関する情報を示しています。これは、主に高度な診断と監視に役立ちます。
行 5 は、若いコレクションに関する詳細情報を示しています。この若いコレクション中に、合計サイズ 1718 KB の、48984 のオブジェクトが昇格されました。若いコレクションには 39.310 ミリ秒かかりました。
行 6 は、ガベージ コレクションの前と後のページ フォールトの統計値を示しています。ガベージ コレクション中のページ フォールトは、ガベージ コレクションの速度を大幅に低下させる可能性があります。
行 7 は、若いコレクション後のナーサリ サイズを示しています。
行 8 にはガベージ コレクション後にすべての Java スレッドを開始するためにかかった時間が示されています。この場合は 0.030 ミリ秒です。
圧縮領域へのポインタが多過ぎるために圧縮が中止された場合、memdbg 冗長出力に示されます。この場合、以下が出力されます。
[memdbg ] Pointerset limit hit, compaction aborted.
コンカレントな古いコレクションのマーク フェーズ中にヒープが一杯になると、デフォルトでは、ガベージ コレクタがコンカレント スイープ フェーズをオーバーライドし、代わりにパラレル スイープを使用します。この場合、以下が出力されます。
[memdbg ] The heap became full during concurrent mark. Running parallel sweep.
JRockit JVM では、古いコレクションの実行時にヒープの部分的な圧縮を行います。圧縮により、ヒープの断片化が削減され、オブジェクト割り当てが高速になります。冗長 compaction ログ モジュールは、圧縮に関する詳細情報を示します。このモジュールのオーバーヘッドは低く、これは、プロダクション環境でこのモジュールを有効にできることを意味しています。
コード リスト 19-10 は、compaction ログ モジュールからの冗長出力の例を示しています。この例は、JRockit JVM R27.4 からのものです。行数を追加しています。
1: [compact] OC 4: 8 parts (max 128), index 8. Type internal, (exceptional false)
2: [compact] Area start: 0x01EC0000, end: 0x03180000
3: [compact] Updated 14130 references in 0 nonmoved and 11700 moved objects
4: [compact] Average compact time ratio: 0.442280
5: [compact] Compaction pause: 2.548 (target 50.000), update ref pause: 10.025 (target 50.000)
6: [compact] Updated 59048 refs (limit: 84386).
7: [compact] Compaction ended at index 15, object end address 0x03179A00.
8: [compact] Summary: 4;8;15;8;1;0;2.548;50.000;10.025;50.000;59048;84386
9: [compact] Adjusting compactsetlimit: 102698
10: [compact] Pause per 1000 refs, current: 0.169920, average: 0.486862. Target pause: 50.000
行 1 は、これから実行される圧縮の概要を示しています。この例では、古いコレクションのシーケンス番号は 4 です。合計 128 のヒープ パーツのうち、インデックス 8 から 8 つのヒープ パーツが圧縮されます。圧縮の種類は内部です、これは、オブジェクトが圧縮領域の内部で移動されることを意味します。圧縮は例外ではありません。つまり、実行に時間がかかり過ぎる場合、圧縮は中止または中断される場合があります。
行 2 は、圧縮領域の開始および終了位置の物理アドレスを示しています。この情報は、高度な診断に役立ちます。
行 3 には、オブジェクトの移動により、圧縮領域内で更新された参照の数に関する統計値が示されています。この例では、11700 のオブジェクトが移動され、14130 の参照が更新されました。
行 4 は、オブジェクトの移動に費やされた時間と移動されたオブジェクトへの参照の更新に費やされた時間の間の平均比率が 0.44 であることを示しています。
行 5 は、圧縮による休止時間の 2 つの要素と、それらの要素の現在の目標休止時間に関する詳細情報を示しています。この例では、オブジェクトの移動には 2.548 ミリ秒しかかかりませんでしたが、移動されたオブジェクトへの参照の更新には 10.025 ミリ秒かかりました。ただし、各要素の目標休止時間は 50 ミリ秒でした。
行 6 は、更新された参照の合計数を示しています。これには、圧縮領域内の参照と、圧縮領域内のオブジェクトをポイントしていた圧縮領域外の参照の両方が含まれています。この情報は、監視およびチューニングに役立ちます。
行 7 は、圧縮の終了インデックスおよび物理アドレスを示しています。この情報は、診断に役立ちます。
行 8 には、マシンで読み取り可能な、この圧縮からの一部の統計の概要が含まれています。この行は、統計値の収集に役立ちます。
行 9 は、圧縮ヒューリスティックが、圧縮設定の制限を調整したことを示しています。圧縮設定の制限によって、それぞれの古いコレクションで実行できる圧縮の量が決まります。
行 10 は、1000 の参照の更新にかかる平均時間についての統計値を示しています。この値は、圧縮設定の制限を算出するための基準として使用されます。
圧縮が中止されるたびに、冗長 compaction ログ モジュールによって、圧縮の中止の原因に関する情報が示されます。以下の例では、ガベージ コレクション スレッドのポインタ マトリックスが上限に達しました。つまり、選択された圧縮領域内のオブジェクトに対するポインタが多くなり過ぎました。
[compact] Pointermatrix for thread '(GC Worker Thread 1)' failed to extend beyond 25817 elements.
-Xverbose:gcpause ログ モジュールは、個々のガベージ コレクションの休止に関する情報を示します。レイテンシの監視、チューニングおよび診断において、この情報は不可欠です。このモジュールのオーバーヘッドは低く、これは、プロダクション環境でこのモジュールを使用できることを意味しています。
パラレルな古いコレクションでは、ガベージ コレクションの間中、すべての Java スレッドが休止されます。そのため、パラレルな古いコレクション中の -Xverbose:gcpause からの出力は、コード リスト 19-11 に示されているように、非常に簡潔です。この例は、JRockit JVM R27.4 からのものです。行数を追加しています。
1: [gcpause] Threads waited for memory 147.424 ms starting at 6.398 s
2: [gcpause] old collection phase 1-0 pause time: 146.861682 ms, (start time: 6.398 s)
3: [gcpause] (pause includes compaction: 10.169 ms (external), update ref: 14.390 ms)
行 1 は、古いコレクションのために、Java スレッドが 147.424 ミリ秒間メモリを待機したことを示しています。この値は、古いコレクションの休止時間とは異なる場合があります。
行 2 は、古いコレクションの「フェーズ 1 ～ -0」での休止時間を示しています。フェーズ 1 は最初のフェーズです。フェーズ 0 はデフォルトのフェーズですが、ガベージ コレクションは実行されていません。つまり、時間測定はフェーズ 1 で開始され、ガベージ コレクタの完了後に終了するため、ガベージ コレクション全体が含まれることになります。
行 3 は、圧縮および圧縮による参照の更新によって発生した休止時間に関する詳細情報をいくつか示しています。
モーストリ コンカレント (または「コンカレント」) な古いコレクションは、間に短い休止が含まれる、複数のコンカレント ガベージ コレクション フェーズから構成されています。
コード リスト 19-12 は、モーストリ コンカレントな古いコレクションからの出力の例を示しています。この例は、JRockit JVM R27.4 からのものです。行数を追加しています。
1: [gcpause] old collection phase 1 pause time: 19.184561 ms, (start time: 24.027 s)
2: [gcpause] old collection phase 4-5 pause time: 25.100956 ms, (start time: 24.720 s)
3: [gcpause] (pause includes yc: 24.456 ms, compaction: 0.230 ms (external), update ref: 0.003 ms)
4: [gcpause] old collection phase 5 pause time: 0.253384 ms, (start time: 24.769 s)
5: [gcpause] old collection phase 5-0 pause time: 1.751061 ms, (start time: 1.391 s)
行 1 は、古いコレクションのフェーズ 1 での休止時間を示しています。フェーズ 1 は、初期マーク フェーズです。
行 2 は、古いコレクションのフェーズ 4 から始まり、フェーズ 5 の始めに終了する休止の休止時間を示しています。このフェーズは、最終マーク フェーズおよび圧縮です。
行 3 は、フェーズ 4 ～ 5 の休止の詳細情報をいくつか示しています。フェーズ 4 で実行された若いコレクションには 24.456 ミリ秒、圧縮には 0.23 ミリ秒、および圧縮後の参照の更新には 0.003 ミリ秒かかりました。この情報は、圧縮の休止時間のチューニングおよび診断に役立ちます。
行 4 は、フェーズ 5 の中ほどでの休止の休止時間を示しています。フェーズ 5 は、コンカレント スイープ フェーズです。ヒープは 2 つのパーツに分けてスイープされます。短い休止は、スイープするパーツの切り替えによって発生します。
行 5 は、フェーズ 5 の終了時の休止の休止時間を示しています。フェーズ 5 では、最終的な統計値が収集され、ガベージ コレクションが終了します。
若いコレクションは、1 回の休止で構成されています。そのため、次の例に示されているように、若いコレクションの gcpause 冗長出力は非常に簡潔です。
[gcpause] nursery collection pause time: 37.832462 ms
-Xverbose:gcreport ログ モジュールは、実行の終了時に、ガベージ コレクション アクティビティの概要を出力します。
コード リスト 19-13 は、gcreport 冗長出力の例を示しています。この例は、JRockit JVM R27.4 からのものです。行数を追加しています。
1: [memory ] Memory usage report
2: [memory ]
3: [memory ] young collections
4: [memory ] number of collections = 5647
5: [memory ] total promoted = 58920467 (size 2144906056)
6: [memory ] max promoted = 219349 (size 10249784)
7: [memory ] total GC time = 37.543 s
8: [memory ] mean GC time = 6.648 ms
9: [memory ] maximum GC Pauses = 59.602 , 71.426, 75.759 ms
10: [memory ]
11: [memory ] old collections
12: [memory ] number of collections = 34
13: [memory ] total promoted = 776698 (size 28208080)
14: [memory ] max promoted = 72997 (size 2655216)
15: [memory ] total GC time = 13.970 s (pause 4.583 s)
16: [memory ] mean GC time = 410.872 ms (pause 134.790 ms)
17: [memory ] maximum GC Pauses = 147.064 , 172.153, 209.094 ms
18: [memory ]
19: [memory ] number of concurrent mark phases = 21
20: [memory ] number of parallel mark phases = 13
21: [memory ] number of concurrent sweep phases = 18
22: [memory ] number of parallel sweep phases = 16
行 3 ～ 9 には、この実行中の若いコレクションに関する情報が示されています。
行 5 は、昇格されたオブジェクトの合計数とそれらの合計サイズ (バイト) を示しています。
行 6 は、1 回の若いコレクション中に昇格されたオブジェクトの最大数とそれらの合計サイズ (バイト) を示しています。
行 7 は、若いコレクションに費やされた合計時間を示しています。
行 8 は、1 回の若いコレクションに費やされた平均時間を示しています。
行 9 は、若いコレクションによって発生した休止時間のうち、長かったものを 3 つ示しています。
行 11 ～ 7 は、古いコレクションに関する統計値を示しています。
行 13 は、古いコレクション中に昇格されたオブジェクトの合計数とそれらの合計サイズ (バイト) を示しています。
行 14 は、1 回の古いコレクション中に昇格されたオブジェクトの最大数とそれらの合計サイズ (バイト) を示しています。
行 15 は、古いコレクションに費やされた合計時間と、古いコレクションによって発生したすべてのガベージ コレクションの休止時間の合計を示しています。
行 16 は、1 回の古いコレクションで費やされた平均時間と、1 回の古いコレクション中の休止時間の合計の平均を示しています。
行 17 は、古いコレクションでの休止時間のうち、長かったものを 3 つ示しています。
行 19 には、コンカレント マーク フェーズの数が示されています。この例では、21 の古いコレクションがコンカレント マークを使用しました。
行 20 は、パラレル マーク フェーズの数を示しています。この例では、13 の古いコレクションがパラレル マークを使用しました。
行 21 は、コンカレント スイープ フェーズの数を示しています。この例では、18 の古いコレクションがコンカレント スイープを使用しました。
行 22 は、パラレル スイープ フェーズの数を示しています。この例では、16 の古いコレクションがパラレル スイープを使用しました。
-Xverbose:referents ログ モジュールは JRockit JVM R27.2 で導入されました。-Xverbose:refobj は JRockit JVM R27.5 で導入された、冗長 referents モジュールに取って代わるモジュールです。
冗長 referents モジュールは、多少のオーバーヘッドを発生させるため、プロダクション環境での使用には適していません。R27.2 での冗長 refobj の info レベルの出力は、負荷が少ないため、プロダクション環境で使用することができます。refobjs の debug レベルの出力は、info レベルの古い冗長 referents の情報に相当し、プロダクションで使用することはできません。
-Xverbose:refobj ログ モジュールは、参照オブジェクトの数と、各ガベージ コレクションでのそれらの処理方法の概要を示します。
コード リスト 19-14 は、refobj 冗長出力の例を示しています。この例は、JRockit JVM R27.5 からのものです。行数を追加しています。
1: [refobj ] SoftRef: Reach: 2 Act: 0 PrevAct: 11 Null: 50
2: [refobj ] WeakRef: Reach: 183 Act: 0 PrevAct: 0 Null: 10
3: [refobj ] Phantom: Reach: 0 Act: 0 PrevAct: 0 Null: 0
4: [refobj ] ObjMoni: Reach: 2 Act: 0 PrevAct: 0 Null: 0
5: [refobj ] Finaliz: Reach: 17 Act: 0 PrevAct: 0 Null: 0
6: [refobj ] WeakHnd: Reach: 306 Act: 0 PrevAct: 0 Null: 0
7: [refobj ] SoftRef: @Mark: 62 @Preclean: 1 @FinalMark: 0
8: [refobj ] WeakRef: @Mark: 178 @Preclean: 15 @FinalMark: 0
9: [refobj ] Phantom: @Mark: 0 @Preclean: 0 @FinalMark: 0
10: [refobj ] ObjMoni: @Mark: 2 @Preclean: 0 @FinalMark: 0
11: [refobj ] Finaliz: @Mark: 0 @Preclean: 17 @FinalMark: 0
12: [refobj ] WeakHnd: @Mark: 0 @Preclean: 105 @FinalMark: 201
13: [refobj ] SoftRef: SoftAliveOnly: 0 SoftAliveAndReach: 0
行 1 ～ 6 は、各参照オブジェクト型、ファイナライザ、弱ハンドルおよびオブジェクト モニタの発生回数を示しています。参照オブジェクトは、以下のように状態で分類されます。
行 7 ～ 12 は、参照オブジェクトがどのガベージ コレクション フェーズで処理されたかを表す統計値を示しています。
行 13 は、ソフト参照としてのみ生存しているソフト参照の数と、同時にハード到達可能でもあるソフト参照の数を示しています。
コード リスト 19-15 で示されているように、古い冗長 referents ログ モジュールと debug レベルの refobj ログ モジュールは、参照オブジェクトおよびリファレントに関する詳細オブジェクトを示します。この例は、JRockit JVM R27.2 からのものです。今後のリリースでは出力の形式が異なる可能性があります。
各参照型は参照クラスおよびリファレントごとに分類されます。ハンドルの場合は、参照は存在しないので、リファレントのみが表示されます。表示されるさまざまなカウンタの値は、存在する各型のインスタンスの数を示しており、それらが到達可能であるかどうか (クリアされているかどうか) も確認できます。
レポートのヘッダ/フッタには、追加的な情報として、どのタイプのコレクションが実行されたのかが表示されます。ヘッダには、最後の古いコレクションからの経過時間と、その時点での空きメモリの量が示されます。また、ソフト参照が存在する場合は、コレクションの対象となったソフト到達可能なリファレントが明示され、そのコレクションを実行した判断基準として、それらのリファレントが get() の呼び出しを通じて最後に参照された時点からの経過時間が表示されます。
| 注意 : | これらの冗長出力は、パフォーマンスを大幅に低下させます。 |
--- Verbose reference objects statistics - heap collection -------
63.7 MB free memory (of 64.0 MB) after last heap GC, finished 0.177 s ago.
Soft references: 0 (0 only soft reachable, 2 cleared this GC)
java/lang/ref/SoftReference: 0 (0, 2)
0 (0, 1) java/lang/StringCoding$CharsetSD
0 (0, 1) [Ljava/lang/String;
Softly reachable referents not used for at least 0.000 s cleared.
Weak references: 10 (0 cleared this GC)
java/lang/ref/WeakReference: 9 (0)
9 (0) java/lang/Class
java/lang/ThreadLocal$ThreadLocalMap$Entry: 1 (0)
1 (0) java/lang/ThreadLocal
Weak object handles: 63 (0 cleared this GC)
35 (0) sun/misc/Launcher$AppClassLoader
28 (0) java/lang/String
Final handles: 10 (0 pending finalization, 0 became pending this GC)
4 (0, 0) java/util/jar/JarFile
3 (0, 0) java/util/zip/Inflater
2 (0, 0) java/io/FileOutputStream
1 (0, 0) java/io/FileInputStream
Phantom references: 2 (0 only phantom reachable, 0 became phantom reachable this
GC)
jrockit/vm/ObjectMonitor: 2 (0, 0)
1 (0, 0) java/lang/Object
1 (0, 0) java/io/PrintStream
--- End of reference objects statistics - heap collection --------
この例では、ガベージ コレクションによって、型がそれぞれ java.lang.StringCoding および java.lang.String のオブジェクトまたはアレイを参照している 2 つのソフト参照がクリアされました。
10 の弱参照、63 の弱オブジェクト ハンドル、10 の最終ハンドルおよび 2 つのファントム参照があります。
JRockit JVM で使用可能なさまざまなログ モジュールのうち、最も使用され、最も役に立つ 2 つが opt と exceptions です。
-Xverbose:opt ログ モジュールは、最適化コンパイラによって実行されたコードの最適化に関する情報を示します。
コード リスト 19-16 は、opt 冗長出力の例を示しています。この例は、JRockit JVM R27.5 からのものです。行数を追加しています。
1: [opt ] #1 5 (0x1c) o0 java/util/Random.acquireSeedLock()V
2: [opt ] #1 5 (0x1c) o0 @0x13AA0000-0x13AA003F 2.43 ms (2.43 ms)
3: [opt ] #2 5 (0x1c) o0 java/util/Random.next(I)I
4: [opt ] #2 5 (0x1c) o0 @0x13AA0370-0x13AA03FF 2.66 ms (20.19 ms)
行 1 および 3 は、最適化された 2 つのメソッドの名前を示しています。
行 2 および 4 は、メソッドのアドレスと、それらの最適化にかかった時間を示しています。
opt の冗長情報を使用して、最適化を診断および監視できます。
-Xverbose:exceptions ログ モジュールは、アプリケーションでスローされるそれぞれの Java 例外を出力します。この情報を使用して、アプリケーションの例外を監視およびトラブルシューティングできます。
コード リスト 19-17 は、冗長 exceptions ログ モジュールからの出力の例の一部を示しています。この例は、Oracle JRockit JVM R27.5 からのものです。各行では、スローされた例外の名前と、ある場合は例外メッセージが示されています。
[excepti][00004] java/lang/NullPointerException
[excepti][00004] java/lang/NullPointerException: null array passed into arraycopy
[excepti][00004] java/lang/ArrayIndexOutOfBoundsException
[excepti][00004] java/lang/ArrayIndexOutOfBoundsException
[excepti][00004] java/lang/NullPointerException: null array passed into arraycopy
-Xverbose:exceptions=debug は、同じ情報を出力しますが、さらに各例外のスタック トレースも示します。
|