2.2.8 拡張verbosegc情報を使用したFullGCの要因の分析方法
SerialGC使用時の拡張verbosegc情報を使用したFullGCの要因の分析方法について説明します。拡張verbosegc情報は，JavaVMオプションである-XX:+HitachiVerboseGCオプションを指定することによって出力できる日立JavaVMのログ情報です。チューニングに役立つ情報のほか，障害要因の分析にも役立つ情報が出力されます。
チューニング実行時に拡張verbosegc情報を参照することで，次の情報を確認できます。
-
GC実行前と実行後の各領域の使用メモリサイズ
-
GCが発生した要因
また，-XX:+HitachiVerboseGCとほかのJavaVMオプションを組み合わせることによって，さらに詳細な情報が出力できます。-XX:+HitachiVerboseGCオプション，およびそのほかのJavaVM拡張オプションの詳細については，「5.2 日立JavaVM拡張オプションの詳細」を参照してください。
(1) 拡張verbosegc情報の出力形式の概要
拡張verbosegc情報は，CopyGCが発生した場合と，FullGCが発生した場合に出力されます。
CopyGCが発生すると，GCの種類として「GC」と出力されます。また，FullGCが発生すると，GCの種類として「Full GC」と出力されます。種類に続いて，それぞれの領域の「＜GC前のメモリサイズ＞->＜GC後のメモリサイズ＞（＜確保済み領域サイズ＞）」が出力されます。
以降に，FullGCが発生した場合の拡張verbosegc情報の出力例を示します。拡張verbosegc情報には，ほかにもGCの発生要因やGCスレッドのCPU時間も出力されます。
拡張verbosegc情報の出力形式の詳細，およびそれぞれのオプションの詳細については，「5. 日立JavaVM起動オプション」を参照してください。
(2) FullGC発生時の拡張verbosegc情報の出力例
ここでは，FullGCの発生時の拡張verbosegc情報の出力例を示します。
(a) New領域メモリサイズに対してTenured領域が不足した場合
New領域（Eden領域とSurvivor領域の合計）で使用しているメモリサイズがTenured領域の最大値に対する未使用メモリサイズを上回った場合の，拡張verbosegc情報の出力例を次に示します。太字の部分がFullGC発生の要因を示す個所です。
… [VGC]<Wed May 11 23:12:05 2005>[GC 27340K->27340K(32704K), 0.0432900 secs][DefNew::Eden: 3440K->0K(3456K)][DefNew::Survivor: 58K->58K(64K)][Tenured: 23841K->27282K(29184K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0156250 secs][Sys: 0.0312500 secs] [VGC]<Wed May 11 23:12:05 2005>[Full GC 30780K->30780K(32704K), 0.2070500 secs][DefNew::Eden: 3440K->1602K(3456K)][DefNew::Survivor: 58K->0K(64K)][Tenured: 27282K->29178K(29184K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0156250 secs][Sys: 0.0312500 secs] …
この出力例からは，次のことが分かります。
-
New領域で使用しているメモリサイズ（3440K＋58K＝3498K）が，Tenured領域の最大値に対する未使用メモリサイズ（29184K−27282K＝1902K）を上回りました。
-
FullGCの要因は，オブジェクトアロケーションの失敗です。
(b) CopyGC時にTenured領域へのオブジェクトの移動に失敗した場合
CopyGCの実施の結果，New領域（Eden領域とSurvivor領域の合計）からTenured領域へのオブジェクトの移動に失敗した場合の，拡張verbosegc情報の出力例を次に示します。太字の部分がFullGC発生の要因を示す個所です。
… [VGC]<Thu Oct 20 11:04:42 2011>[GC 26418K->26418K (29696K), 0.0000000 secs][DefNew::Eden:8188K->8188K(8192K)][DefNew::Survivor: 1021K->1021K(1024K)][Tenured:17208K->17208K (20480K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0000000 secs][Sys: 0.0000000 secs][IM: 877K, 1104K, 0K][TC: 9][DOE: 0K, 0] [VGC]<Thu Oct 20 11:04:42 2011>[Full GC 26418K->6450K(29696K), 0.0156250 secs][DefNew::Eden:8188K->0K(8192K)][DefNew::Survivor:1021K->0K(1024K)][Tenured:17208K->6450K(20480K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:PromotionFail][User: 0.0156250 secs][Sys: 0.0000000 secs][IM: 925K, 1104K, 0K][TC: 9][DOE: 0K, 0]
この出力例からは，次のことが分かります。
-
FullGCの要因は，CopyGCによる，New領域からTenured領域へのオブジェクトの移動の失敗です。
(c) オブジェクトアロケーション時にTenured領域が不足した場合
アロケーションしたいメモリサイズ（newで作成するJavaオブジェクトのサイズ）がTenured領域の未使用メモリサイズを上回る場合の，拡張verbosegc情報の出力例を次に示します。太字の部分がFullGC発生の要因を示す個所です。
… [VGC]<Wed May 11 23:53:18 2005>[GC 28499K->28490K(32704K), 0.0540590 secs][DefNew::Eden: 808K->0K(3456K)][DefNew::Survivor: 64K->62K(64K)][Tenured: 27626K->28428K(29184K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0156250 secs][Sys: 0.0312500 secs] [VGC]<Wed May 11 23:53:18 2005>[Full GC 28490K->8959K(32704K), 0.1510380 secs][DefNew::Eden: 0K->0K(3456K)][DefNew::Survivor: 62K->0K(64K)][Tenured: 28428K->8959K(29184K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0156250 secs][Sys: 0.0312500 secs] …
この出力例からは，次のことが分かります。
-
Tenured領域の未使用メモリサイズ（29184K−28428K＝756K）を上回るメモリサイズのJavaオブジェクトを，newで作成しようとしました。
-
FullGCの要因は，オブジェクトアロケーションの失敗です。
(d) Tenured領域の未使用メモリサイズが10,000バイトを下回った場合
CopyGC実施の結果，確保済みTenured領域の未使用メモリサイズが10,000バイトを下回った場合の，拡張verbosegc情報の出力例を次に示します。太字の部分がFullGC発生の要因を示す個所です。
… [VGC]<Fri May 25 15:21:33 2007>[GC 15436K->15416K(19840K), 0.0111825 secs][DefNew::Eden: 4413K->0K(4416K)][DefNew::Survivor: 512K->509K(512K)][Tenured: 10511K->14906K(14912K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0000000 secs][Sys: 0.0000000 secs] [VGC]<Fri May 25 15:21:33 2007>[Full GC 15416K->8622K(19840K), 0.0284614 secs][DefNew::Eden: 0K->0K(4416K)][DefNew::Survivor: 509K->0K(512K)][Tenured: 14906K->8622K(14912K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0312500 secs][Sys: 0.0000000 secs] …
この出力例からは，次のことが分かります。
-
1行目のCopyGCでNew領域からTenured領域にオブジェクトが移動したことによって，Tenured領域の使用済みメモリサイズが10,511キロバイトから14,906キロバイトに増加しました。これによって，確保済みTenured領域の未使用メモリサイズが14,912キロバイト−14,906キロバイト＝6キロバイトとなり，10,000バイト（約10キロバイト）を下回りました。
-
1行目のCopyGCの原因は，オブジェクトアロケーションの失敗です。1行目のCopyGCと2行目のFullGCは，Javaプログラムに制御が戻る前に連続して発生します。
(e) CopyGC実施時にTenured領域の拡張が発生した場合
CopyGC実施時のTenured領域へのオブジェクトの移動によって，確保済みTenured領域の拡張が発生した場合の，拡張verbosegc情報の出力例を次に示します。太字の部分がFullGC発生の要因を示す個所です。
… [VGC]<Fri May 25 15:42:00 2007>[GC 12745K->10151K(15872K), 0.0048346 secs][DefNew::Eden: 4416K->0K(4416K)][DefNew::Survivor: 137K->512K(512K)][Tenured: 8192K->9639K(10944K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0156250 secs][Sys: 0.0000000 secs] [VGC]<Fri May 25 15:42:00 2007>[GC 14563K->14536K(19072K), 0.0104957 secs][DefNew::Eden: 4412K->0K(4416K)][DefNew::Survivor: 512K->510K(512K)][Tenured: 9639K->14026K(14144K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0156250 secs][Sys: 0.0000000 secs] [VGC]<Fri May 25 15:42:00 2007>[Full GC 14536K->8610K(19072K), 0.0287254 secs][DefNew::Eden: 0K->0K(4416K)][DefNew::Survivor: 510K->0K(512K)][Tenured: 14026K->8610K(14144K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:ObjAllocFail][User: 0.0312500 secs][Sys: 0.0000000 secs] …
この出力例からは，次のことが分かります。
-
2行目のCopyGCでNew領域からTenured領域へのオブジェクトが移動したことによって，Tenured領域が最低でも14,026キロバイト以上必要になりました。このため，確保済みTenured領域サイズが10,944キロバイトから14,144キロバイトに拡張されました。
-
2行目のCopyGCの原因は，オブジェクトアロケーションの失敗です。2行目のCopyGCと3行目のFullGCは，Javaプログラムに制御が戻る前に連続して発生します。
(f) java.lang.System.gc()メソッドが実行された場合
アプリケーション内でjava.lang.System.gc()メソッドが実行された場合の，拡張verbosegc情報の出力例を次に示します。太字の部分がFullGC発生の要因を示す個所です。
… [VGC]<Mon Apr 18 20:36:29 2005>[Full GC 330K->150K(3520K), 0.0387690 secs][DefNew::Eden: 330K->0K(2048K)][DefNew::Survivor: 0K->0K(64K)][Tenured: 0K->150K(1408K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:System.gc][User: 0.0156250 secs][Sys: 0.0312500 secs] …
この出力例からは，次のことが分かります。
-
FullGCの要因は，アプリケーション内でのjava.lang.System.gc()メソッド呼び出しです。
(g) Metaspace領域へのオブジェクトアロケーションに失敗した場合
Metaspace領域にアロケーションしたいメモリサイズが確保済みMetaspace領域の未使用メモリサイズを上回る場合の，拡張verbosegc情報の出力例を次に示します。太字の部分がFullGC発生の要因を示す個所です。
… [VGC]<Wed Jan 07 01:56:13 2015>[Full GC 11273K->6037K(15872K), 0. 0060004 secs][DefNew::Eden: 442K->0K(4416K)][DefNew::Survivor: 512K->0K(512K)][Tenured: 10319K->6037K(10944K)][Metaspace: 22811K(24520K, 24576K)->22811K(24520K, 24576K)][class space: 10758K(10988K, 11008K)->10758K(10988K, 11008K)][cause:MetaspaceAllocFail][User: 0.0312002 secs][Sys: 0.0000000 secs] …
この出力例からは，次のことが分かります。
-
Metaspace領域にアロケーションしようとしたメモリサイズが，確保済みMetaspace領域の未使用メモリサイズ（24576キロバイト−22811キロバイト＝1765キロバイト）を上回りました。
-
FullGCの要因は，Metaspace領域のアロケーションの失敗です。
(h) javagcコマンド実行によるFullGCが発生した場合
javagcコマンドを実行した場合の，拡張verbosegc情報の出力例を次に示します。太字の部分がFullGC発生の要因を示す個所です。
… [VGC]<Mon Apr 18 21:46:50 2005>[Full GC 369K->189K(3520K), 0.0403010 secs][DefNew::Eden: 369K->0K(2048K)][DefNew::Survivor: 0K->0K(64K)][Tenured: 0K->189K(1408K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:JavaGC Command][User: 0.0156250 secs][Sys: 0.0312500 secs] …
この出力例からは，次のことが分かります。
-
FullGCの要因は，javagcコマンド実行です。
(i) jheapprofコマンド実行によるFullGCが発生した場合
jheapprofコマンドを実行した場合の，拡張verbosegc情報の出力例を次に示します。太字の部分がFullGC発生の要因を示す個所です。
… [VGC]<Mon Apr 18 21:46:50 2005>[Full GC 369K->189K(3520K), 0.0403010 secs][DefNew::Eden: 369K->0K(2048K)][DefNew::Survivor: 0K->0K(64K)][Tenured: 0K->189K(1408K)][Metaspace: 3634K(4492K, 4492K)->3634K(4492K, 4492K)][class space: 356K(388K, 388K)->356K(388K, 388K)][cause:JHeapProf Command][User: 0.0156250 secs][Sys: 0.0312500 secs] …
この出力例からは，次のことが分かります。
-
FullGCの要因は，jheapprofコマンド実行です。