unnamed

Javaとか、http://twitter.com/sugarlife

G1GCのログの読み方

この記事は Java Advent Calendar 2012 の3日目です！
前の日は @btnrouge さんの「HotSpotの変遷からみたJava SE 7の考察」でした。次の日は @making さんです！

G1GCのログ

G1GC (Garbage First Garbage Collection) が JDK 7u4 から正式に導入されました。この新しいGCの詳細は、幸いなことに @nari3 さんが日本語でG1GC本を執筆されており、これを読むことで殆どを把握することができます。やったね！ちなみに英語の論文等で読もうとすると、例えばこうなります。
学習の高速道路は整っていますが、更に理解の掘り下げやチューニングのために、実際に動かしながらログを読もうとすると、今までの形式とはすっかり変わってしまっているのでその読みにくさに絶望します。そのため、ここではログの出力がそれぞれどんな意味なのかをまとめていきたいと思います。
なお、ここでは以下のJVMを利用し、JDKに付属しているサンプル java2demo.jar を利用してログを出しました。

$ java -server -version
java version "1.7.0_09-icedtea"
OpenJDK Runtime Environment (fedora-2.3.3.fc17.1-x86_64)
OpenJDK 64-Bit Server VM (build 23.2-b09, mixed mode)

G1GC のサイクル

ログを見る前にG1GCの挙動を軽くおさらいしましょう。G1GCは以下のような2つのフェーズに分けられ、6つの処理をサイクルしています。

  • Concurrent Marking Cycle Phase
    1. Initial Mark (Stop the world)
    2. Root Region Scanning (Concurrent)
    3. Concurrent Marking (Concurrent)
    4. Remark (Stop the world)
    5. Cleanup (Stop the world & Concurrent)
  • Evacuation Pause Phase
    1. Copying (Stop the world)
      • このCopyingはYoung Regionを対象としたYoungモードとYoungとOldの両方を対象としたMixedの二種類ある。

-XX:+PrintGC

-XX:PrintGC (-verbosegc) を付けた場合のログは次のようになります。

:
5.325: [GC pause (young) 19M->12M(27M), 0.0270580 secs]
6.184: [GC pause (young) (initial-mark) 18M->12M(27M), 0.0112730 secs]
6.196: [GC concurrent-root-region-scan-start]
6.197: [GC concurrent-root-region-scan-end, 0.0013980]
6.197: [GC concurrent-mark-start]
6.217: [GC concurrent-mark-end, 0.0201330 sec]
6.217: [GC remark, 0.0021420 secs]
6.220: [GC cleanup 13M->13M(27M), 0.0001140 secs]
6.946: [GC pause (young) 18M->13M(27M), 0.0089250 secs]
7.464: [GC pause (mixed) 17M->13M(27M), 0.0118070 secs]
8.388: [GC pause (young) 20M->13M(27M), 0.0104410 secs]
:

まだ読みやすいですね。
Evacuation Pause Phase(と、initial-mark)ごとに「処理名 GC前->GC後(最大)のヒープサイズ, その処理にかかった時間(sec)」が記述されています。Concurrent Marking Phaseは各処理の開始時点(処理名-start)と終了時点(処理名-end)の2回出力され、終了の時点でその処理にかかった時間(sec)が記されています。ただし、Cleanup処理に関しては、オブジェクトの生存情報が再計算されるため、Evacuation Pause Phaseと同様に処理前後のヒープサイズが記されています。
このログからは全体ヒープ量とGC時間、そしてGCによる停止時間の概算が解ります。単純なメモリリークと停止時間を見るだけなら、さしあたり十分な情報は取れます。

-XX:+PrintGCDetails

-XX:+PrintGCDetailsを付けた場合、Evacuation Pause Phase の各 GC Worker Thread が、それぞれの処理に懸かった時間を詳細に出力するため、途端に読みづらくなります。

：
//-XX:PrintGCと一緒。GC Pauseに懸かった総処理時間(secs)
4.685: [GC pause (young), 0.01147000 secs] 
   // 並列動作しているGC worker threadsの経過時間。これ以降の1インデント下がっている部分は並列で実行されており、その処理にかかった時間。
   [Parallel Time:  11.4 ms] 
      // 各workerの処理開始時間(Javaプロセス開始時点からの経過時間(ms))
      [GC Worker Start (ms):  4685.4  4685.5  4685.5  4685.5
       Avg: 4685.5, Min: 4685.4, Max: 4685.5, Diff:   0.1] 
      // 各workerがroot情報をスキャンするのにかかった時間。
      [Ext Root Scanning (ms):  5.4  5.3  5.3  5.6
       Avg:   5.4, Min:   5.3, Max:   5.6, Diff:   0.3] 
      // 各workerがRemembered Sets(RS)を更新するのにかかった時間。
      [Update RS (ms):  3.1  3.2  3.1  3.0
       Avg:   3.1, Min:   3.0, Max:   3.2, Diff:   0.2] 
         [Processed Buffers : 2  3  3  2
          Sum: 10, Avg: 2, Min: 2, Max: 3, Diff: 1] 各workerのバッファーを更新した数。
      //  各workerがRemembered Sets(RS)をスキャンするのにかかった時間。
      [Scan RS (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0, Diff:   0.0]
      // 各workerが生存オブジェクトをRegionsからCollection Set(CSet)にコピーするのに懸かった時間
      [Object Copy (ms):  2.9  2.8  3.0  2.9
       Avg:   2.9, Min:   2.8, Max:   3.0, Diff:   0.2] 
      // 各workerの終了処理にかかった時間。
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0, Diff:   0.0]
         [Termination Attempts : 1  1  1  0
          Sum: 3, Avg: 1, Min: 0, Max: 1, Diff: 1]
      // 各workerが上の一連の処理を終わらせた時間(Javaプロセス開始時点からの経過時間(ms))
      [GC Worker End (ms):  4696.8  4696.8  4696.9  4697.0
       Avg: 4696.9, Min: 4696.8, Max: 4697.0, Diff:   0.2] 
      // 各workerの一連の処理時間。StartとEndから単純に計算すると小数点以下の誤差がでる。
      [GC Worker (ms):  11.3  11.3  11.4  11.4
       Avg:  11.4, Min:  11.3, Max:  11.4, Diff:   0.1]
      // 各workerの一連の処理以外の時間。この時間はParallel Timeに含まれる。
      [GC Worker Other (ms):  0.1  0.1  0.1  0.1
       Avg:   0.1, Min:   0.1, Max:   0.1, Diff:   0.1]
   // Card Tableを初期化するのにかかった時間。1スレッドで実行される。
   [Clear CT:   0.0 ms] 
   // 以降のCollection Set関係の合計処理時間。
   [Other:   0.1 ms]
      // Collection Setの選択に懸かった時間。
      [Choose CSet:   0.0 ms] 
      // Reference Objectsに懸かった時間。
      [Ref Proc:   0.0 ms]
      // ReferenceQueueに参照を追加するのに懸かった時間。
      [Ref Enq:   0.0 ms]
      // Collection Setを開放するのに懸かった時間。
      [Free CSet:   0.0 ms]
   // ヒープに対する各領域の占有量。
   [Eden: 5120K(5120K)->0B(3072K) Survivors: 1024K->1024K Heap: 15M(20M)->10M(20M)] 
 [Times: user=0.01 sys=0.00, real=0.01 secs]
4.805: [GC pause (mixed), 0.02731400 secs]
   [Parallel Time:  27.2 ms]
      [GC Worker Start (ms):  4805.2
			:(中略)
   [Eden: 3072K(3072K)->0B(5120K) Survivors: 0B->1024K Heap: 13M(20M)->12M(20M)]
 [Times: user=0.03 sys=0.00, real=0.03 secs]
5.284: [GC pause (young) (initial-mark), 0.02324400 secs]
   [Parallel Time:  22.9 ms]
      [GC Worker Start (ms):  5284.3
			：(中略)
   [Eden: 4096K(4096K)->0B(3072K) Survivors: 1024K->1024K Heap: 15M(20M)->12M(20M)]
 [Times: user=0.02 sys=0.00, real=0.02 secs]
5.308: [GC concurrent-root-region-scan-start]
5.314: [GC concurrent-root-region-scan-end, 0.0054690]
5.314: [GC concurrent-mark-start]
5.396: [GC concurrent-mark-end, 0.0818220 sec]
// ref-procはReference processingに懸かった時間。
5.398: [GC remark 5.398: [GC ref-proc, 0.0000310 secs], 0.0069840 secs]
 [Times: user=0.01 sys=0.00, real=0.01 secs]
5.410: [GC cleanup 13M->13M(20M), 0.0001110 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs]
5.566: [GC pause (young), 0.01728500 secs]
   [Parallel Time:  17.2 ms]
：

長々と出力されたログ(とOpenJDKのソース)を見ていきましたが、重要なのはGC pause処理部分に以下の一文が追加されたことです。

[Eden: 5120K(5120K)->0B(3072K) Survivors: 0B->1024K Heap: 15M(20M)->10M(20M)]

これにより、GC処理前後のヒープ全体だけではなく、各ヒープ領域の状況も確認できます。上記の例では、Eden領域がGCによって5120K占有していたものが全てEden領域から解放/移動されて0Bになり、最大値が5120Kから3072Kに減っていることを示しています。また、Survivors領域は今回のGCによって0Bから1024KBに拡張されたことが解ります。

おまけ

-XX:UnlockDiagnosticVMOptions を使うことで有効になる出力用のオプションです。

-XX:G1PrintRegionLivenessInfo

全ての各Regionに存在する生存オブジェクトをConcurrent Marking Cycle Phaseの最後(Cleanup中)に出力します。

-XX:+G1PrintHeapRegions

Regionに関するイベントを各Regionがcommit/allocated/reclaimedした際に出力します。かなりの量のログが出力されます。

-XX:G1LogLevel=(fine|finer|finest)

JavaOne2012 の G1 Garbage Collector Performance Tuning というセッションで紹介されたJVMオプションです。fine==-XX:+PrintGC、finer==-XX:PrintGCDetails、finest≒-XX:+PrintGCDetails (いくつかの細かい情報が追加されている)として出力します。が、現在未対応のため、導入された際にどうなるかは不明です。


以上、G1GCのログの読み方でした。
思った以上にGCサイクルの挙動が詳細に出力されますが、より詳細に追いかけるためにはDiagnosticなJVMオプションも使う必要があります。しかし、人の目で追いかけるにはもはや苦痛を伴うレベルであるため、トラブルシュートやパフォーマンスチューニングを行うにあたっては、@kimuchi583 さんのようにG1GCに最適化された(情報をザッピングできる)ビューワー*1を開発する必要があるなと感じています。
次は @making さんの番です！

*1:http://www.slideshare.net/kimuchi583/jjug-javaone-2012-san-francisco-ltg1gc