GC Dump

概要

 

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
  

 
 
性能調査が加速する日本エクセムのMaxGauge