catch-img

GC Dump - 日本エクセム株式会社 Oracle 技術情報


目次[非表示]

  1. 1.基本情報
  2. 2.Sun Hotspot JVM
    1. 2.1.基本フォーマット
    2. 2.2.Collector種類別のフォーマット
      1. 2.2.1.Serial Collector
      2. 2.2.2.Parallel Collector
      3. 2.2.3.CMS Collector
    3. 2.3.Memory LeakとGC Dump
  3. 3.IBM JVM
    1. 3.1.Throughput Collector
    2. 3.2.Response Time Collector
    3. 3.3.Concurrent Generational Collector
  4. 4.関連情報


基本情報

 GC DumpはJVMのHeap使用状況を把握するための最も基本的なツールです。GC Dumpを使用すると、次のような情報を得ることができます。

・GCの発生時刻
・GC実行時間
・GC発生当時Heap Usage

 GC Dumpは、システムに対する負荷が小さいため、オペレーティングシステムでGC Dumpを残すオプションを選択ことをお勧めします。もしメモリの問題が発生した場合GC Dumpだけで情報が不足する場合には、Heap Dumpを利用して、追加の分析を行うことができます。ただし、Heap Dumpは、システムに大きな負荷を与えることができるので、必要な場合にのみ使用することをお勧めします。


Sun Hotspot JVM

 Sun Hotspot JVMは、次のようなオプションを利用してGC Dumpを制御します。

・PrintGCDetails:GC実行の詳細情報を出力します。
・PrintGCTimeStamps:GCの発生時刻情報を出力します。
・PrintHeapAtGC:GC発生時Heap詳細情報を出力します。
・-Xloggc:: GC Dumpを保存するファイル名を指定します。別に指定しない場合Consoleに直接出力されます。


基本フォーマット

 GC Dumpの出力結果は、基本的に次のようなフォーマットを持ちます。

・時間(JVM開始以降の時間)
・Generation名(DefNew+ Tenured、PSYoungGen+ PSOldGen、ParNew+ CMS-concurrent-mark)
・Heap Usage変動:{GC前Usage} - >{GC後Usage}({Total Size})
 たとえば896K->64K(960K)であればGC前896Kを使用しており、GC後64Kでの使用量が減り、
 全体のサイズは960Kという意味です。
・GC所要時間:GCを実行するのにかかった時間

次に簡単な例を示します。

0.186:[GC0.186:[DefNew:896K->64K(960K)、0.0022028 secs]896K->434K(5056K)、0.0023143 secs]

上記の例から、読みとれることを説明します。

・JVM駆動後0.186秒に実行されたGC作業です。
・DefNewはDefault Serial CollectorでのYoung Generationを意味します。つまりMinor GCが行われました。
・Young Generationのサイズは960Kであり、896Kを使用しており、GC作業によって64Kのみを使用してました。
 つまり、GCによって832K(896-64)がCollectionされた事になります。
 Minor GC作業に0.0022028秒かかっています。
・全体Heapサイズは5056Kであり、Minor GCによって使用量が896Kで434Kに減少しました。
・Minor GCを含めてGCを実行するのに所要される時間は、0.0023143秒です。


Collector種類別のフォーマット

Serial Collector

 Serial CollectorはUseSerialGCオプションを利用して活性化されます。Serial CollectorはYoung GenerationとOld Generationクリーンアップ操作の両方にSerial方式、すなわち一つのThread(Single Thread)を使用してGC処理を実行します。Serial CollectorによるGC Dumpは、次の3つの種類のログが記録されます。

 -  Minor GC
0.186:[GC0.186:[DefNew:896K->64K(960K)、0.0022028 secs]896K->434K(5056K)、0.0023143 secs]
 -  Major GC(Promotion Failureが発生)
1.388:[GC1.388:[DefNew:3839K->383K(3840K)、0.0064941 secs]
 1.394:[Tenured:50563K->49784K(50592K)、0.1538941 secs]53367K->49784K(54432K)、0.1605942 secs]
 -  Full GC
2.425:[Full GC2.425:[Tenured:60543K->60543K(60544K)、0.1595010 secs]65087K->64787K(65088K)、
 [Perm:391K->391K(12288K)]、0.1596044 secs]

Serial CollectorでのGC Dumpの完全なサンプルは、Serial Collector GC Log Sampleを参照ください。


Parallel Collector

 Parallel CollectorはUseParallelGCオプションを利用して活性化されます。 Parallel CollectorはYoung Generationクリーンアップ操作にParallel方式、すなわち、複数のThreadを使用します。 Enterprise級の大型Applicationは、非常に大きなサイズのYoung Generationを使用することになります。この場合、Minor GCに多くの時間がかかることがあります。 Parallel CollectorはMinor GC作業にMulti Threadを使用することにより、Minor GCによるPause Timeを最小限に抑えています。 UseParallelOldGCオプションを使用すると、Old GenerationにもParallel方式を使用することができます。

 Parallel CollectorによるGC Dumpは、次のような種類のログが記録されます。

-  Minor GC
0.893:[GC [PSYoungGen:28023K-> 10311K(25728K)] 49157K-> 38181K(56000K)、0.0556451 secs]
 -  Full GC
1.460:[Full GC [PSYoungGen:4032K-> 0K(26880K)] [PSOldGen:49402K-> 51007K(66752K)] 53434K-> 51007K(93632K)
[PSPermGen:2003K-> 2003K(12288K)]、0.1678135 secs]

Parallel CollectorでのGC Dumpの完全なサンプルは、Parallel Collector GC Log Sampleを参照ください。


CMS Collector

 CMS CollectorはUseConcMarkSweepGCオプションによって活性化されます。 CMS CollectorはFull GCによるPause Timeを最小限に抑えるためOld Generationのクリーンアップ操作をConcurrent方式で進行します。 CMS CollectorによるGC Dumpは、次のような種類のログが記録されます。

 -  Minor GC
0.138:[GC 0.138:[ParNew:26240K-> 3264K(29504K)、0.0503947 secs] 26240K-> 8241K(521024K)、0.0505461 secs]
 -  Concurrent GC
2.593:[GC [1 CMS-initial-mark:259838K(491520K)] 263365K(521024K)、0.0023419 secs]
2.596:[CMS-concurrent-mark-start]
4.357:[CMS-concurrent-mark:0.655 / 1.761 secs]
4.357:[CMS-concurrent-preclean-start]
4.419:[CMS-concurrent-preclean:0.040 / 0.062 secs]
4.419:[CMS-concurrent-abortable-preclean-start]
4.428:[CMS-concurrent-abortable-preclean:0.007 / 0.010 secs
4.588:[GC [YG occupancy:3619 K(29504 K)] 4.588:[Rescan(parallel)、0.0148329 secs] 4.603:
    [weak refs processing、0.0000291 secs] [1 CMS-remark:422939K(491520K)] 
    426559K(521024K )、0.0149645 secs]
4.688:[CMS-concurrent-sweep-start]
5.425:[CMS-concurrent-sweep:0.302 / 0.737 secs]
5.425:[CMS-concurrent-reset-start]
5.489:[CMS-concurrent-reset:0.014 / 0.064 secs]

CMS CollectorでのGC Dumpの完全なサンプルは、CMS Collector GC Log Sampleを参照ください。


Memory LeakとGC Dump

 Memory Leakが発生した場合、GC Dumpは、次のような典型的なパターンを示します。

1.564:[GC 1.564:[DefNew:4543K-> 447K(4544K)、0.0074507 secs] 55108K-> 52239K(65088K)、
    0.0075322 secs]
1.576:[GC 1.576:[DefNew:4543K-> 447K(4544K)、0.0084435 secs] 56335K-> 54675K(65088K)、
    0.0085257 secs]
1.589:[GC 1.589:[DefNew:4543K-> 447K(4544K)、0.0072420 secs] 58771K-> 55902K(65088K)、
    0.0073378 secs]
1.600:[GC 1.600:[DefNew:4543K-> 447K(4544K)、0.0073699 secs] 59998K-> 57130K(65088K)、
    0.0074590 secs]
1.610:[GC 1.610:[DefNew:4543K-> 447K(4544K)、0.0075529 secs] 61226K-> 58357K(65088K)、
    0.0076395 secs]
1.621:[GC 1.621:[DefNew:4543K-> 447K(4544K)、0.0074387 secs] 62453K-> 59585K(65088K)、
    0.0075247 secs]
1.632:[GC 1.632:[DefNew:4543K-> 4543K(4544K)、0.0000433 secs] 63681K-> 63681K(65088K)、
    0.0001028 secs]
1.632:[Full GC 1.632:[Tenured:59137K-> 57835K(60544K)、0.2154176 secs] 63681K-> 
    57835K(65088K)、[Perm:392K-> 391K(12288K)]、0.2155249 secs]
1.851:[GC 1.851:[DefNew:4096K-> 447K(4544K)、0.0057781 secs] 61931K-> 59063K(65088K)、
    0.0058661 secs]
1.860:[GC 1.860:[DefNew:4543K-> 447K(4544K)、0.0071495 secs] 63159K-> 60291K(65088K)、
    0.0072347 secs]
1.870:[GC 1.871:[DefNew:4543K-> 4543K(4544K)、0.0000335 secs] 1.871:[Tenured:59843K->
    60543K(60544K)、0.1666050 secs] 64387K-> 61519K(65088K)、0.1667678 secs]
2.038:[Full GC 2.038:[Tenured:60543K-> 60543K(60544K)、0.1665533 secs] 62712K->
    61855K(65088K)、[Perm:391K-> 391K(12288K)]、0.1666667 secs]
2.234:[Full GC 2.234:[Tenured:60543K-> 60543K(60544K)、0.1607975 secs] 65087K->
    64658K(65088K)、[Perm:391K-> 391K(12288K)]、0.1609087 secs]
2.425:[Full GC 2.425:[Tenured:60543K-> 60543K(60544K)、0.1595010 secs] 65087K->
    64787K(65088K)、[Perm:391K-> 391K(12288K)]、0.1596044 secs]

上記のパターンは、次のように解釈することができます。

・Minor GCが継続して起こるにもかかわらず、Heapの使用量が増え続けるだけです。
・Young GenerationとOld Generationがすべて満杯になった時点で、継続してFull GCのみ発生します。
・最終的にOut Of Memory Errorが発生することになります。


IBM JVM

 IBM JVMは、以下のオプションを使用して、GC Dumpを制御します。

verbosegc:GC Dumpを残すことを指定します。 (例えば、-verbosegc)
verbosegclog:GC Dumpを残すFile名を指定します。 (例えば、-Xverbosegclog:gc.log)

IBM JVMは、Sun Hotspot JVMとは異なり、XML形式のログを残します。一般的なフォーマット(Generational Collectionを使用していない場合)は、次のとおりです。

af type = "tenured" id = "1" timestamp = "Tue Oct 23 00:33:18 2007" intervalms = "0.000"
 
gc type = "global" id = "1" totalid = "1" intervalms = "0.000"

expansion type = "tenured" amount = "1048576" newsize = "5242880" timetaken = 
          "0.010" reason = "insufficient free space following gc" /

soa freebytes = "1520336" totalbytes = "5066752" percent = "30" /

loa freebytes = "176128" totalbytes = "176128" percent = "100" /
 
totalms = "5.590" /

用語の意味は次のとおりです。

・afはAllocation Failureの略で、新しいObjectのメモリを割り当て受ける失敗したことを意味します。
・gcはGarbage Collectionの略で、Allocation FailureによってGCが発生したことを意味します。
・soaはSmall Object Areaの略でサイズが小さいObjectが居住する空間を意味します。
・loaはLarge Object Areaの略でサイズが大きいObjectが居住する空間を意味します。
・expansionはFree Memory不足によりHeap Expansionが発生したことを意味します。
・intervalms、timetaken、timems、totalmsなどの値を使用してGC実行時間情報を知ることができます。

この用語を用いて、上記のGC Logを分析すると、次のような事実を知ることができます。

・GC操作の前のTotal Heapは4M(4194304)であり、Free Heapは200K(209408)でした。
・GCの過程でExpansionが発生し1M(1048576)ほどHeapサイズが増加しました。
・Markに5.154ms、Sweepに0.138msかかりれCompactionは起こりませんでした。
・GCの操作後、Free Heapは1.6M(1695728)、Total Heapは5M(5242880)に増加しました。


Throughput Collector

 Throughput Collectorはgcpolicy(-Xgcpolicy:optthruput)オプションによって活性化されます。IBM JVMは基本的にGenerationを使用していないので、Minor GCとMajor GCの区分がありません。Generationを使用していないため、常にすべてのHeap領域がGC対象となります。これが、gc type=”global”が意味するところです。


Response Time Collector

 Response Time Collectorはgcpolicy(-Xgcpolicy:optavgpause)オプションによって活性化されます。Response Time CollectorもまたGenerationを使用していません。したがってThroughput Collectorのようにgc type=”global”で表現されます。


Concurrent Generational Collector

 Concurrent Generational Collectorはgcpolicy(-Xgcpolicy:gencon)オプションによって活性化されます。IBM JDK1.5で新たに追加されSun Hotspot JVMのCMS Collectorと非常によく似た技法を使用します。Concurrent Generational CollectorはGenerationに基づいています。したがってMinor GCとMajor GCのような区分が存在します。IBM JVMは、Scavenger GCとGlobal GCという用語が使用されます。上記の例では、af type=”nursery”、gc type=”scavenger”が意味するのはNursery、すなわちYoung GenerationでGCが発生し、Scavenger GC、すなわちMinor GCが発生したことを意味します。


関連情報

1.Garbage Collector


CONTACT

他社に頼らず自社でデータベースを監視・運用をしませんか?
MaxGaugeがサポートします

お役立ち資料は
こちらから

不明点がある方は、
こちらからお問い合わせください

お電話でのお問い合わせはこちら

平日 10時~18時

人気記事ランキング

タグ一覧