| Oracle® JRockit JDKツール・ガイド リリースR28 B61440-03 |
|
 前 |
 次 |
-Xverboseコマンドライン・オプションは、Oracle JRockit JVMからの冗長出力を可能にします。この冗長出力を使用して、監視、チューニングおよび診断を行うことができます。この章では、いくつかの最も役に立つ冗長モジュールとそれらの出力の解釈方法について説明します。
|
注意: 出力はJVMリリース間で異なる可能性があります。出力の正確な形式は、任意の時点で変更される場合があります。 |
この章では、次の節について説明します。
表2-1に、メモリー管理およびガベージ・コレクションのためにJRockit JVMで使用できる冗長ログ・モジュールの一覧を示します。
表2-1 メモリー管理のための冗長モジュール
| ログ・モジュール | 説明 | 用途 |
|---|---|---|
memory |
基本的なガベージ・コレクション情報 |
チューニングおよび監視 |
nursery |
ナーサリ情報 |
チューニングおよび監視 |
memdbg |
メモリー管理情報 |
チューニング、監視および診断 |
compaction |
圧縮情報 |
チューニング、監視および診断 |
gcpause |
ガベージ・コレクションの休止時間 |
チューニング、監視および診断 |
gcreport |
ガベージ・コレクションの概要 |
チューニングおよび監視 |
refobj |
参照オブジェクト情報 |
監視および診断 |
alloc |
割当ておよびメモリー不足情報 |
監視および診断 |
ほとんどの冗長モジュールが、複数のログ・レベルで使用できます。この項では、memdbgモジュールを除いては、デフォルトの(info)ログ・レベルについてのみ説明します。これは一般的なチューニングおよび監視に最も役立つレベルです。
-Xverbose:memory(または-Xverbose:gc)モジュールは、ガベージ・コレクション・イベントに関する基本的な情報を提供します。このモジュールのオーバーヘッドは非常に低く、これは、本番環境でもこのモジュールを有効にできることを意味しています。
JVMの起動時に、memoryモジュールは、メモリー管理システムの構成に関する基本的な数値をいくつか表示し、ガベージ・コレクションの出力の読み方を示します。
例2-1は、memoryログ・モジュールからの冒頭の出力の例を示しています。行番号が追加されています。
例2-1 memoryモジュールの冒頭の出力
1: [INFO ][memory ] Running with 32 bit heap and compressed references. 2: [INFO ][memory ] GC mode: Garbage collection optimized for throughput, strategy: Generational Parallel Mark & Sweep. 3: [INFO ][memory ] Heap size: 65536KB, maximum heap size: 3145728KB, nursery size: 32768KB. 4: [INFO ][memory ] <start>-<end>: <type> <before>KB-><after>KB (<heap>KB), <time> ms, sum of pauses <pause> ms. 5: [INFO ][memory ] <start> - start time of collection (seconds since jvm start). 6: [INFO ][memory ] <type> - OC (old collection) or YC (young collection). 7: [INFO ][memory ] <end> - end time of collection (seconds since jvm start). 8: [INFO ][memory ] <before> - memory used by objects before collection (KB). 9: [INFO ][memory ] <after> - memory used by objects after collection (KB). 10: [INFO ][memory ] <heap> - size of heap after collection (KB). 11: [INFO ][memory ] <time> - total time of collection (milliseconds). 12: [INFO ][memory ] <pause> - sum of pauses during collection (milliseconds). 13: [INFO ][memory ] Run with -Xverbose:gcpause to see individual phases.
行1は、圧縮参照が使用されているかどうかを示しています。
行2は、この実行で使用されたガベージ・コレクション・モードと、初期のガベージ・コレクション方式について説明しています。
行3は、初期および最大ヒープ・サイズと、初期ナーサリ・サイズを示しています。
行4-13は、ガベージ・コレクションの出力の形式について説明しています。
memoryモジュールは、ガベージ・コレクションごとに1行を表示します。
例2-2は、memoryモジュールからの冗長出力の例を示しています。行番号が追加されています。
例2-2 memoryモジュールのガベージ・コレクションの出力
1: [INFO ][memory ] [YC#1] 0.981-1.019: YC 35001KB->33131KB (65536KB), 0.038 s, sum of pauses 37.851 ms, longest pause 37.851 ms. 2: [INFO ][memory ] [YC#2] 1.688-1.706: YC 58229KB->45536KB (65536KB), 0.019 s, sum of pauses 18.683 ms, longest pause 18.683 ms. 3: [INFO ][memory ] [OC#1] 1.706-1.718: OC 65536KB->57671KB (86176KB), 0.012 s, sum of pauses 10.364 ms, longest pause 10.364 ms. 4: [INFO ][memory ] [YC#3] 1.997-2.006: YC 65143KB->55299KB (86176KB), 0.008 s, sum of pauses 8.328 ms, longest pause 8.328 ms.
ガベージ・コレクションの各出力はタイムスタンプから始まります。これはJVMが起動してからの時間(秒)です。これらの行の形式は例2-1の行4で説明されています。
行1、2および4は、若いコレクションからの出力です。行1の若いコレクションでは、ヒープのサイズが35001KBから33131KBに削減されています。
行3は古いコレクションからの出力であり、ヒープのサイズが65536KBから57671KBに削減されています。
ページ・フォールトは、メモリー・アクセスを遅くします。また、ガベージ・コレクション中のページ・フォールトにより、ガベージ・コレクションにかかる時間が長くなる可能性があります。このため、冗長memoryログ・モジュールは、ガベージ・コレクション中のページ・フォールトの数がヒープ内のページ数の5%を超えた場合に警告を表示します。この出力はWindowsプラットフォームでは使用できません。
例2-3はページ・フォールトの警告を示しています。
-Xverbose:nurseryログ・モジュールは、若いコレクションおよびナーサリのサイズ変更に関する詳細情報を提供します。この情報の一部は、JRockit JVMを監視およびチューニングするために役立ちます。オーバーヘッドは非常に低く、これは、本番環境でこのモジュールを有効にできることを意味しています。
例2-4は、若いコレクションおよび古いコレクション中のnurseryログ・モジュールからの出力を示しています。行番号が追加されています。
例2-4 nurseryモジュールの若いコレクションの出力
1: [INFO ][nursery] [YC#2] Young collection 2 started. This YC is running while the OC is in phase: not running. 2: [INFO ][nursery] [YC#2] Setting forbidden area for keeparea: 0x40ffdff0-0x417fdfe8. 3: [INFO ][nursery] [YC#2] Next keeparea will start at 0x417fdfe8 and end at 0x41ffe000. 4: [INFO ][nursery] [OC#1] Setting keepAreaMarkers[0] to 0x43883f00. 5: [INFO ][nursery] [OC#1] Setting keepAreaMarkers[1] to 0x43dc8860. 6: [INFO ][nursery] [OC#1] Setting keepAreaMarkers[2] to 0x43f9ba88. 7: [INFO ][nursery] [OC#1] Next keeparea will start at 0x43dc8860 and end at 0x43f9ba88.
行1 - 3は若いコレクションの出力([YC#2]で表示)で、行4 - 7は古いコレクションの出力([OC#1]で表示)です。
行1は、若いコレクションのシーケンス番号を示しています。また、これは、若いコレクションは実行されていますが、古いコレクションは実行されていないことも示しています。その他の古いコレクションのフェーズには、マーキング、プレクリーニングおよびスイーピングがあります。これらはコンカレントな古いコレクションのコンカレント・フェーズです。
行2 - 7には、保持領域のサイズおよび位置に関連する情報が含まれています。この情報は高度な診断に役立ちます。
一部のガベージ・コレクションのモードおよび方式では、実行時にナーサリのサイズを調整してパフォーマンスを最適化します。nurseryログ・モジュールは、ナーサリのサイズ調整の計算およびナーサリのサイズ変更に関する情報をいくつか示します。
例2-5は、古いコレクションからのナーサリのサイズ調整の出力を示しています。行番号が追加されています。
例2-5 nurseryモジュールのナーサリのサイズ調整の出力
1: [INFO ][nursery] [OC#1] Nursery size increased from 0KB to 7474KB. Nursery list consists of 5 parts. 2: [INFO ][nursery] [OC#1] Nursery size remains at 7474KB. Nursery list consists of 5 parts.
行1は、ナーサリ・サイズが増加した範囲と、ナーサリに含まれる要素の数を示しています。
行2は、ナーサリのサイズが変更されなかったことを示しています。
-Xverbose:memdbgログ・モジュールは、メモリー管理の全概要を示すための複数のメモリー関連ログ・モジュールを起動する別名です。これらのモジュールからの出力は、個々のモジュールで説明されています。memdbgログ・モジュールはメモリー・モジュールをdebugレベルに設定します。debugレベルにおけるメモリーからの出力のみをこの項で説明します。この情報は、-Xverbose:memory=debugと設定することでも取得できます。
memdbg冗長出力のオーバーヘッドは低いため、本番環境で使用できます。
例2-6は、memdbg冗長モジュールからの冒頭の出力を示しています。行番号が追加されています。
例2-6 memdbgモジュールの冒頭の出力
1: [DEBUG][memory ] Minimum TLA size is 2048 bytes. 2: [DEBUG][memory ] Preferred TLA size is 65536 bytes. 3: [DEBUG][memory ] TLA waste limit is 2048 bytes. 4: [DEBUG][memory ] Nursery object limit max is 65536 bytes. 5: [DEBUG][memory ] Nursery object limit percentage is 1.0%. 6: [DEBUG][memory ] Java heap regions: 7: [000000003fffe000 - 0000000043ffe000] rw-- (pagesize=0x1000) 8: [0000000043ffe000 - 000000007fffe000] ---- 9: [0000000080000000 - 0000000100000000] ---- 10: 64MB committed, 3008MB reserved. 11: [DEBUG][memory ] Initial and maximum number of gc threads: 8, of which 8 parallel threads, 4 concurrent threads, and 8 yc threads. 12: [DEBUG][memory ] Maximum nursery percentage of free heap is 95%. 13: [DEBUG][memory ] Prefetch distance in workpacket: 4. Packet size: 493 objects. 14: [DEBUG][memory ] Using prefetch linesize: 64 bytes chunks: 512 bytes pf_dist: 256 bytes.
行1 - 5は、最小および推奨のスレッド・ローカル領域のサイズ、TLAの浪費上限、およびナーサリで割り当てられるオブジェクトのサイズに関する情報を示しています。これらの値は、ヒープ・サイズ、ガベージ・コレクタ、およびJRockit JVMのリリースによって異なります。
行6 - 10は、Javaヒープに対するメモリー・マップと、仮想アドレス領域でコミットおよび確保されているメモリーの量を表示します。
複数のヒープ・リージョンが存在する可能性があります。リージョンは連続するアドレスに位置している可能性があります(ただし必須ではありません)。
行11は、ガベージ・コレクション・スレッドの数を示しています。
行12は、ナーサリの最大サイズを示しています。
行13と14は、プリフェッチに関する情報を示しています。これらは高度な診断とチューニングに役立ちます。
memdbgモジュールは、ガベージ・コレクション出力に情報を追加します。一部のチューニングおよび診断作業において、この情報は不可欠です。出力はガベージ・コレクションの種類によって異なります。
例2-7は、パラレルな古いコレクションからのmemdbg冗長出力を示しています。行番号が追加されています。
例2-7 memdbgモジュールのパラレルな古いコレクションの出力
1: [DEBUG][memory ] [OC#1] GC reason: Allocation request failed. 2: [DEBUG][memory ] [OC#1] 1.706: OC started. 3: [DEBUG][memory ] [OC#1] Starting parallel marking phase. 4: [DEBUG][memory ] [OC#1] SemiRef phase Finalizers run in single threaded mode. 5: [DEBUG][memory ] [OC#1] SemiRef phase WeakJNIHandles run in single threaded mode. 6: [DEBUG][memory ] [OC#1] SemiRef phase ClassConstraints run in single threaded mode. 7: [DEBUG][memory ] [OC#1] SemiRef phase FinalMemleak run in single threaded mode. 8: [DEBUG][memory ] [OC#1] Removing 4 permanent work packets from pool, now 60 packets. 9: [DEBUG][memory ] [OC#1] Total mark time: 5.145 ms. 10: [DEBUG][memory ] [OC#1] Ending marking phase. 11: [DEBUG][memory ] [OC#1] Starting parallel sweeping phase. 12: [DEBUG][memory ] [OC#1] Total sweep time: 4.735 ms. 13: [DEBUG][memory ] [OC#1] Ending sweeping phase. 14: [DEBUG][memory ] [OC#1] Expanded the heap from 65536KB to 86176KB. 15: [DEBUG][memory ] [OC#1] Page faults before OC: 1, page faults after OC: 1, pages in heap: 21544. 16: [DEBUG][memory ] [OC#1] Nursery size after OC: 7474KB. (Free: 7472KB Parts: 5)
行1は、ガベージ・コレクションの理由を示しています。
行2は、古いコレクションが開始したときのタイムスタンプを示しています。
行3 - 10は、マーク・フェーズ中に行われた処理を示しています。このマーク・フェーズは、休止およびコンカレント・フェーズを含めて5.145ミリ秒かかりました。このケースでは、Javaスレッドはマーク・フェーズ中ずっと休止していました。
行11 - 13はスイープ・フェーズを示しています。
行14は、Javaヒープ・サイズが増加した範囲を示しています。
行15は、古いコレクションの前と後のページ・フォールトの数を示しています。ガベージ・コレクション中のページ・フォールトは、ガベージ・コレクションの速度を低下させる可能性があります。
行16は、古いコレクション後のナーサリの大きさを示しています。
memdbgメモリー・モジュールは、ガベージ・コレクション出力に有効な情報を追加します。チューニングおよび診断の評価において、この情報は不可欠です。出力はガベージ・コレクションの種類によって異なります。
例2-8は、コンカレントな古いコレクションからのmemdbg冗長出力を示しています。行番号が追加されています。
例2-8 memdbgモジュールのコンカレントな古いコレクションの出力
1: [DEBUG][memory ] [OC#1] GC reason: Allocation request failed. 2: [DEBUG][memory ] [OC#1] 1.768: OC started. 3: [DEBUG][memory ] [OC#1] Starting initial marking phase (OC1). 4: [DEBUG][memory ] [OC#1] SemiRef phase Finalizers run in single threaded mode. 5: [DEBUG][memory ] [OC#1] SemiRef phase WeakJNIHandles run in single threaded mode. 6: [DEBUG][memory ] [OC#1] SemiRef phase ClassConstraints run in single threaded mode. 7: [DEBUG][memory ] [OC#1] Initial marking phase promoted 0 objects (0KB). 8: [DEBUG][memory ] [OC#1] Starting concurrent marking phase (OC2). 9: [DEBUG][memory ] [OC#1] Concurrent mark phase lasted 5.137 ms. 10: [DEBUG][memory ] [OC#1] Starting precleaning phase (OC3). 11: [DEBUG][memory ] [OC#1] Precleaning phase lasted 0.300 ms. 12: [DEBUG][memory ] [OC#1] Starting final marking phase (OC4). 13: [DEBUG][memory ] [OC#1] SemiRef phase Finalizers run in single threaded mode. 14: [DEBUG][memory ] [OC#1] SemiRef phase WeakJNIHandles run in single threaded mode. 15: [DEBUG][memory ] [OC#1] SemiRef phase ClassConstraints run in single threaded mode. 16: [DEBUG][memory ] [OC#1] SemiRef phase FinalMemleak run in single threaded mode. 17: [DEBUG][memory ] [OC#1] Final marking phase promoted 0 objects (0KB). 18: [DEBUG][memory ] [OC#1] Adding 27 temporary work packets to permanent pool, now 91 packets. 19: [DEBUG][memory ] [OC#1] Total mark time: 11.528 ms. 20: [DEBUG][memory ] [OC#1] Ending marking phase. 21: [DEBUG][memory ] [OC#1] Starting concurrent sweeping phase. 22: [DEBUG][memory ] [OC#1] Total sweep time: 1.732 ms. 23: [DEBUG][memory ] [OC#1] Ending sweeping phase. 24: [DEBUG][memory ] [OC#1] Expanded the heap from 65536KB to 93216KB. 25: [DEBUG][memory ] [OC#1] GC Trigger is now 13.2%, was 12.0%. 26: [DEBUG][memory ] [OC#1] Page faults before OC: 1, page faults after OC: 1, pages in heap: 23304. 27: [DEBUG][memory ] [OC#1] Nursery size after OC: 29260KB. (Free: 29256KB Parts: 9)
行1は、ガベージ・コレクションの理由を示しています。
行2は、古いコレクションが開始したときのタイムスタンプを示しています。
行3 - 20は、マーク・フェーズ中に行われた処理を示しています。行19は、休止およびコンカレント・フェーズを含めた、マーク・フェーズにかかった時間を示しています。
行21 - 23は、スイープ・フェーズを示しています。行20は、スイープ・フェーズにかかった時間を示しています。
行24は、Javaヒープ・サイズが増加した範囲を示しています。
行25は、ガベージ・コレクション・トリガーに関する情報を示しています。
行26は、古いコレクションの前と後のページ・フォールトの数を示しています。ガベージ・コレクション中のページ・フォールトは、ガベージ・コレクションの速度を低下させる可能性があります。
行27は、古いコレクション後のナーサリ・サイズを示しています。
例2-9は、若いコレクションからのmemdbg冗長出力を示しています。行番号が追加されています。
例2-9 memdbgモジュールの若いコレクションの出力
1: [DEBUG][memory ] [YC#1] GC reason: Allocation request failed. 2: [DEBUG][memory ] [YC#1] 0.981: YC started. 3: [DEBUG][memory ] [YC#1] Returning duplicate cardTablePart entry 2 (0x4201e000-0x4202e000) 4: [DEBUG][memory ] [YC#1] SemiRef phase Finalizers run in single threaded mode. 5: [DEBUG][memory ] [YC#1] SemiRef phase WeakJNIHandles run in single threaded mode. 6: [DEBUG][memory ] [YC#1] SemiRef phase ClassConstraints run in single threaded mode. 7: [DEBUG][memory ] [YC#1] YC promoted 26760 objects (24201KB). 8: [DEBUG][memory ] [YC#1] Page faults before YC: 1, page faults after YC: 1, pages in heap: 16384. 9: [DEBUG][memory ] [YC#1] Nursery size after YC: 32768KB. (Free: 24574KB Parts: 1)
行1には、ガベージ・コレクションの理由が示されています。この例では、割当てが失敗したためにガベージ・コレクションが開始されました。これは、若いコレクションが開始される一般的な理由です。
行2は、若いコレクションが開始したときのタイムスタンプを示しています。
行3は、複数のスレッドが同じメモリーを処理しようとすると何が起きるかを示しています。これはdebugレベルであることに注意してください。
行4 - 6は、若いコレクションの様々なフェーズに関する情報を示しています。
行7は、若いコレクション中に昇格されたオブジェクトの数(およびサイズ)を示しています。
行8は、ガベージ・コレクションの前と後のページ・フォールトの統計値を示しています。ガベージ・コレクション中のページ・フォールトは、ガベージ・コレクションの速度を低下させる可能性があります。
行9は、若いコレクション後のナーサリ・サイズを示しています。
コンカレントな古いコレクションのマーク・フェーズ中にヒープが一杯になると、デフォルトでは、ガベージ・コレクタがコンカレント・スイープ・フェーズをオーバーライドし、かわりにパラレル・スイープを使用します。例2-10は、この動作で生成される出力を示しています。
JRockit JVMでは、古いコレクションの実行時にヒープの部分的な圧縮を行います。圧縮により、ヒープの断片化が削減され、オブジェクト割当てが高速になります。冗長compactionログ・モジュールは、圧縮に関する情報を示します。このモジュールのオーバーヘッドは低く、これは、本番環境でこのモジュールを有効にできることを意味しています。
例2-11は、compactionログ・モジュールからの冗長出力を示しています。行番号が追加されています。
例2-11 compactionモジュールの古いコレクションの出力
1: [INFO ][compact] [OC#1] Compaction reason: Normal. 2: [INFO ][compact] [OC#1] Compacting 256 of 4096 parts at index 3840. Compaction type is external. Exceptional: No. 3: [INFO ][compact] [OC#1] Compaction area start: 0x43bfe000, end: 0x43ffe000. Timeout: 100.000 ms. 4: [INFO ][compact] [OC#1] Compactset limit (per thread): 37487 (dynamic), not using matrixes. 5: [INFO ][compact] [OC#1] Adjusted compaction area to start at 0x43bfe170 and end at 0x43ffe000. 6: [INFO ][compact] [OC#1] Average compact time ratio (move phase/total time): 0.855877. 7: [INFO ][compact] [OC#1] Too few references, doubling compact ratio. 8: [INFO ][compact] [OC#1] Adjusting compactset limit to 248535. 9: [INFO ][compact] [OC#1] Pause per 1000 refs, current: 0.201178, average: 0.201178. Target pause: 50.000. 10: [INFO ][compact] [OC#1] Compaction time, total: 4.191 ms (target 100.000 ms). 11: [INFO ][compact] [OC#1] Compaction moved 3967 objects and left 0 objects. Total moved size 4125680B. 12: [INFO ][compact] [OC#1] Compaction added 4193936B of free memory in 1 parts. 13: [INFO ][compact] [OC#1] Compaction time, move phase: 3.587 ms (target 50.000 ms). 14: [INFO ][compact] [OC#1] Compaction time, update phase: 0.604 ms (target 50.000 ms). 15: [INFO ][compact] [OC#1] Found 3967 references. Internal: 0 External: 3967. 16: [INFO ][compact] [OC#1] Updated 3967 references. Internal: 0 External: 3967.
行1は、圧縮の理由を示しています。この場合は、通常の圧縮が古いコレクションによってトリガーされています。圧縮のその他の理由としては、空きメモリーが不足しているため割当てリクエストでより大きな圧縮が求められることや、ヒープが縮小していることが考えられます。
行2は、これから実行される圧縮の概要を示しています。この例では、合計4096のヒープ・パーツのうち、索引3840から256のヒープ・パーツが圧縮されます。圧縮の種類は外部です、これは、オブジェクトが圧縮領域の外部に移動されることを意味します。圧縮は例外ではありません。つまり、実行に時間がかかり過ぎる場合、圧縮は中止される場合があります。
行3は、圧縮領域の開始および終了位置の物理アドレスと、この圧縮の実行が許可されている時間を示しています。この情報は、高度な診断に役立ちます。
行4は、現在のcompactset制限を示しています。compactsetには圧縮領域への参照が含まれ、このセットのサイズによって、1つの古いコレクションの間にどれくらいの圧縮を実行するかが決まります。
行5は、圧縮領域がどのように調整されたかを示しています。ヒューリスティックが圧縮領域を調整するため、境界をまたがるアクティブ・オブジェクトはありません。
行6 - 9はヒューリスティックからの情報です。圧縮にかかった時間に基づくcompactsetへの変更が示されています。
行10 - 12は圧縮の結果を示しています。圧縮にかかった時間、移動されたオブジェクトの数、およびアロケータに戻された空きメモリーの量です。
行13 - 14は、圧縮による休止時間の2つの要素と、それらの要素の現在の目標休止時間に関する詳細情報を示しています。この例では、オブジェクトの移動には3.587ミリ秒かかりましたが、移動されたオブジェクトへの参照の更新には0.604ミリ秒かかりました。ただし、各要素の目標休止時間は50ミリ秒でした。
行15 - 16は、圧縮領域で見つかり、移動されたオブジェクトにしたがって更新された参照の数を示しています。この例では、3967の参照すべてが見つかって更新されています(これは正常な動作です)。内部参照は圧縮領域内で見つかり、外部参照は圧縮領域外のオブジェクトに起因しています。この情報は、監視およびチューニングに役立ちます。
圧縮が停止されるたびに、冗長compactionログ・モジュールによって、スキップされた圧縮の原因に関する情報が示されます。例2-12では、ガベージ・コレクション・スレッドのcompactsetが上限に達しました。つまり、選択された圧縮領域内のオブジェクトに対するポインタが多くなり過ぎました。例外的なケースでは、データ構造を拡張しようとしたときに使用できるネイティブ・メモリーが不足しているため、圧縮がスキップされる可能性があります。
-Xverbose:gcpauseログ・モジュールは、個々のガベージ・コレクションの休止に関する情報を示します。レイテンシの監視、チューニングおよび診断において、この情報は不可欠です。このモジュールのオーバーヘッドは低く、これは、本番環境でこのモジュールを使用できることを意味しています。
パラレルな古いコレクションでは、ガベージ・コレクションの間中、すべてのJavaスレッドが休止されます。そのため、パラレルな古いコレクション中の-Xverbose:gcpauseからの出力は、例2-13に示されているように、非常に簡潔です。行番号が追加されています。
例2-13 gcpauseモジュールのパラレルな古いコレクションの出力
1: [INFO ][gcpause] [OC#1] [---] 11.511 ms (1.706000-1.718000) OC 2: [INFO ][gcpause] [OC#1] [con] 0.039 ms (1.706000-1.707000) OC:PreGC 3: [INFO ][gcpause] [OC#1] [pau] 10.364 ms (1.707000-1.717000) OC:Main 4: [INFO ][gcpause] [OC#1] [con] 1.064 ms (1.717000-1.718000) OC:PostGC
行1は、この古いコレクションが11.511ミリ秒かかったことを示す概要です。
行2 - 4は、コレクション内の個々の部分に対する時間を示しています。conは、Java実行と同時に行われる部分を意味し、pauはJava実行内の休止時間を意味します。
モーストリ・コンカレント(またはコンカレント)な古いコレクションは、間に短い休止が含まれる、複数のコンカレント・ガベージ・コレクション・フェーズから構成されています。
例2-14は、モーストリ・コンカレントな古いコレクションからの出力を示しています。行番号が追加されています。
例2-14 gcpauseモジュールのコンカレントな古いコレクションの出力
1: [INFO ][gcpause] [OC#1] [---] 14.946 ms (1.768000-1.783000) OC 2: [INFO ][gcpause] [OC#1] [con] 0.058 ms (1.768000-1.769000) OC:PreGC 3: [INFO ][gcpause] [OC#1] [pau] 5.180 ms (1.769000-1.774000) OC:Initial 4: [INFO ][gcpause] [OC#1] [con] 5.393 ms (1.774000-1.779000) OC:ConcurrentMark 5: [INFO ][gcpause] [OC#1] [pau] 3.112 ms (1.779000-1.782000) OC:Main 6: [INFO ][gcpause] [OC#1] [con] 1.128 ms (1.782000-1.783000) OC:PostGC
行1は、古いコレクションにかかった合計時間を示しています。
行2 - 6は、コレクション内の個々の部分に対する時間を示しています。conは、Java実行と同時に行われる部分を意味し、pauはJava実行内の休止時間を意味します。
-Xverbose:gcreportログ・モジュールは、実行の終了時に、ガベージ・コレクション・アクティビティの概要を表示します。
例2-15は、gcreport冗長出力を示しています。行番号が追加されています。
例2-15 gcreportモジュールの出力
1: [INFO ][gcrepor] 2: [INFO ][gcrepor] Memory usage report: 3: [INFO ][gcrepor] 4: [INFO ][gcrepor] Young Collections: 5: [INFO ][gcrepor] number of collections = 30. 6: [INFO ][gcrepor] total promoted = 166897 (size 170523360). 7: [INFO ][gcrepor] max promoted = 26760 (size 24781800). 8: [INFO ][gcrepor] total YC time = 0.380 s (total paused 0.378 s). 9: [INFO ][gcrepor] mean YC time = 12.670 ms (mean total paused 12.596 ms). 10: [INFO ][gcrepor] maximum YC Pauses = 29.256 , 37.851, 55.795 ms. 11: [INFO ][gcrepor] 12: [INFO ][gcrepor] Old Collections: 13: [INFO ][gcrepor] number of collections = 5. 14: [INFO ][gcrepor] total promoted = 0 (size 0). 15: [INFO ][gcrepor] max promoted = 0 (size 0). 16: [INFO ][gcrepor] total OC time = 0.128 s (total paused 0.119 s). 17: [INFO ][gcrepor] mean OC time = 25.579 ms (mean total paused 23.739 ms). 18: [INFO ][gcrepor] maximum OC Pauses = 16.818 , 26.550, 51.602 ms. 19: [INFO ][gcrepor] 20: [INFO ][gcrepor] 21: [INFO ][gcrepor] number of internal compactions = 3. 22: [INFO ][gcrepor] number of external compactions = 2. 23: [INFO ][gcrepor] 1 of these were stopped because they timed out. 24: [INFO ][gcrepor]
行4 - 10には、この実行中の若いコレクションに関する情報が示されています。
行5は、若いコレクションの合計数を示しています。
行6は、昇格されたオブジェクトの合計数とそれらの合計サイズ(バイト)を示しています。
行7は、1回の若いコレクション中に昇格されたオブジェクトの最大数とそれらの合計サイズ(バイト)を示しています。
行8は、若いコレクションに費やされた合計時間を示しています。
行9は、1回の若いコレクションに費やされた平均時間を示しています。
行10は、若いコレクションによって発生した休止時間のうち、長かったものを3つ示しています。
行12 - 18は、古いコレクションに関する統計値を示しています。
行13は、古いコレクションの合計数を示しています。
行14は、古いコレクション中に昇格されたオブジェクトの合計数とそれらの合計サイズ(バイト)を示しています。
行15は、1回の古いコレクション中に昇格されたオブジェクトの最大数とそれらの合計サイズ(バイト)を示しています。
行16は、古いコレクションに費やされた合計時間と、古いコレクションによって発生したすべてのガベージ・コレクションの休止時間の合計を示しています。
行17は、1回の古いコレクションで費やされた平均時間と、1回の古いコレクション中の平均休止数を示しています。
行18は、古いコレクションでの休止時間のうち、長かったものを3つ示しています。
行21は、内部圧縮の数を示しています。
行22は、外部圧縮の数を示しています。
行23は、タイムアウトが原因で1つの圧縮が停止したことを示しています。
-Xverbose:refobjログ・モジュールは、参照オブジェクトの数と、各ガベージ・コレクションでのそれらの処理方法の概要を示します。
例2-16は、refobj冗長出力を示しています。行番号が追加されています。
例2-16 refobjモジュールの出力
1: [INFO ][refobj ] [YC#1] SoftRef: Reach: 10 Act: 0 PrevAct: 0 Null: 0 2: [INFO ][refobj ] [YC#1] WeakRef: Reach: 14 Act: 0 PrevAct: 0 Null: 0 3: [INFO ][refobj ] [YC#1] Phantom: Reach: 0 Act: 0 PrevAct: 0 Null: 0 4: [INFO ][refobj ] [YC#1] ClearPh: Reach: 0 Act: 0 PrevAct: 0 Null: 0 5: [INFO ][refobj ] [YC#1] Finaliz: Reach: 4 Act: 2 PrevAct: 0 Null: 0 6: [INFO ][refobj ] [YC#1] WeakHnd: Reach: 49 Act: 0 PrevAct: 0 Null: 0 7: [INFO ][refobj ] [YC#1] SoftRef: @Mark: 10 @Preclean: 0 @FinalMark: 0 8: [INFO ][refobj ] [YC#1] WeakRef: @Mark: 11 @Preclean: 0 @FinalMark: 3 9: [INFO ][refobj ] [YC#1] Phantom: @Mark: 0 @Preclean: 0 @FinalMark: 0 10: [INFO ][refobj ] [YC#1] ClearPh: @Mark: 0 @Preclean: 0 @FinalMark: 0 11: [INFO ][refobj ] [YC#1] Finaliz: @Mark: 0 @Preclean: 0 @FinalMark: 6 12: [INFO ][refobj ] [YC#1] WeakHnd: @Mark: 0 @Preclean: 0 @FinalMark: 49 13: [INFO ][refobj ] [YC#1] SoftRef: SoftAliveOnly: 10 SoftAliveAndReach: 0 14: [INFO ][refobj ] [YC#1] NOTE: This count only applies to a part of the heap.
行1 - 6は、各参照オブジェクト型、ファイナライザ、弱ハンドルおよびオブジェクト・モニターの発生回数を示しています。参照オブジェクトはステータスで分類されます。
Reachable(到達可能): 到達可能なリファレントを持つ参照オブジェクト。よりハードなレベルで到達可能なリファレントは到達可能と見なされます。たとえば、ソフト参照のリファレントが、ハード到達可能でもある場合は到達可能です。
Activated(アクティブ化されている): アクティブ化されている参照は、この参照よりハードなレベルではリファレントが到達可能ではない参照です。つまり、参照をクリアするか、または参照キューに置くことができます。
Previously Activated(以前にアクティブ化されている): 以前のガベージ・コレクションでアクティブ化されているが、まだクリアされていない参照は、以前にアクティブ化されている参照として分類されます。
Null(Null): Null参照は、参照オブジェクトの参照はnullですが、参照オブジェクト自体はまだ存在している参照です。
行7 - 12は、参照オブジェクトがどのガベージ・コレクション・フェーズで処理されたかを表す統計値を示しています。
行13は、ソフト参照としてのみ生存しているソフト参照の数と、同時にハード到達可能でもあるソフト参照の数を示しています。
-Xverbose:allocログ・モジュールはメモリー割当てに関する情報を提供します。このモジュールはR28.0で導入されました。
例2-17は、alloc出力を示しています。行番号が追加されています。
例2-17 allocモジュールの出力
1: [INFO ][alloc ] [YC#1] Pending requests at 'Before YC' - Total: 1, TLAs: 1 (approx 65536 bytes), objects: 0 (0 bytes). Max age: 0. 2: [INFO ][alloc ] [YC#1] Satisfied 0 object and 1 tla allocations. Pending requests went from 1 to 0. 3: [INFO ][alloc ] [YC#1] Pending requests at 'After YC' - Total: 0, TLAs: 0 (approx 0 bytes), objects: 0 (0 bytes). Max age: 0.
行1は、ガベージ・コレクション前のオブジェクトの割当てキューのステータスに関する情報を示しています。
行2は、このコレクションの結果、正常に処理された割当てリクエストの数を示しています。
行3では、ガベージ・コレクション後のオブジェクトの割当てキューのステータスに関する情報が示されています。この情報を行1の情報と比較して、オブジェクト割当てが適切に実行されているかどうかを知ることができます。ガベージ・コレクションの終了時点に割当てキューに多数のオブジェクトがある場合は、重度の断片化などにより、オブジェクト割当てが困難であることを示している可能性があります。
JRockit JVMで使用可能な様々なログ・モジュールのうち、最も使用され、最も役に立つ2つがoptとexceptionsです。
-Xverbose:optログ・モジュールは、最適化コンパイラによって実行されたコードの最適化に関する情報を示します。
例2-18は、opt冗長出力を示しています。行番号が追加されています。
例2-18 optモジュールの出力
1: [INFO ][opt ][00036] #1 (Opt) ObjAlloc.main([Ljava/lang/String;)V 2: [INFO ][opt ][00036] #1 3.756-3.758 0x0000000100060000-0x000000010006004E 2.10 ms 128KB 7633 bc/s (2.10 ms 7633 bc/s)
行1は、最適化された2つのメソッドの名前を示しています。
行2は、メソッドのアドレスと、それらの最適化にかかった時間を示しています。
optの冗長情報を使用して、最適化を診断および監視できます。
-Xverbose:exceptionsログ・モジュールは、アプリケーションでスローされるそれぞれのJava例外を表示します。この情報を使用して、アプリケーションの例外を監視およびトラブルシューティングできます。
例2-19は、冗長exceptionsログ・モジュールからの出力を示しています。各行では、スローされた例外の名前と、ある場合は例外メッセージが示されています。
例2-19 exceptionsモジュールの出力
[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は、同じ情報を出力し、各例外のスタック・トレースも示します。
