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

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

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

・時間（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秒です。

 -  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]

-  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]

 -  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]

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が発生することになります。

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

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操作の前の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）に増加しました。

1.Garbage Collector