はじめに

JVMのGCログ出力について調べたのでその備忘録です。
以下は実行環境詳細です。

１．OS
Windows10
２．JDKバージョン
Java(TM) SE Runtime Environment (build 15.0.1+9-18)
Java HotSpot(TM) 64-Bit Server VM (build 15.0.1+9-18, mixed mode, sharing)

Xlogオプション

以下の書式でログの出力設定を行います。-Xlogは、HotSpot JVMでのロギング用の一般的なロギング構成オプション。

-Xlog[:[what][:[output][:[decorators][:output-options[,...]]]]]

詳しいオプションの設定方法は、 javaの拡張ランタイム・オプション - Oracle Help Center を参照。

GCログ出力例

GCログを理解するために、2パターンのオプション設定でログ出力して解釈してみました。

パターン①

Java起動コマンド

java -Xlog:gc=info:file= c:\log.txt:uptime,level,tags :filecount=5,filesize=20M -jar test.jar

出力結果

[0.012s][info][gc] Using G1
[19.103s][info][gc ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 26M->10M(254M) 22.107ms

ログ解釈

JVMが起動してから 0.012 秒後にG1GC (*GC方式の一つ) を使用。
JVMが起動してから 19.103 秒後に、New領域を対象とするGC が発生。
ヒープ領域の使用量がGCにより26Mから10Mに縮小 (ヒープ領域の容量は254M)。
GCに22.107 ミリ秒かかった (Pause が付いている場合は、STW時間)。

パターン②

Java起動コマンド

java -Xlog:gc= info,gc+heap =info,gc+cpu= info:file=c:\log.txt :uptime,level,tags -jar test.jar

出力結果

[0.012s][info][gc] Using G1
[19.103s][info][gc,heap ] GC(0) Eden regions: 10->0(8)
[19.103s][info][gc,heap ] GC(0) Survivor regions: 0->2(2)
[19.103s][info][gc,heap ] GC(0) Old regions: 0->1
[19.103s][info][gc,heap ] GC(0) Archive regions: 0->0
[19.103s][info][gc,heap ] GC(0) Humongous regions: 3->3
[19.103s][info][gc ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 26M->10M(254M) 22.107ms
[19.103s][info][gc,cpu ] GC(0) User=0.00s Sys=0.00s Real=0.02s

ログ解釈

JVMが起動してから 0.012 秒後にG1GC (*GC方式の一つ) を使用。
JVMが起動してから 19.103 秒後に、Eden領域 で使用されているリージョン数が10から0に減少。
GC後のEden領域のリージョン数 (Capacity) は8に変化。
JVMが起動してから 19.103 秒後に、Survivor 領域で使用されているリージョン数が0から2に増加。
GC後のSurvivor領域のリージョン数 (Capacity) は2に変化。
JVMが起動してから 19.103 秒後に、Old 領域で使用されているリージョン数が0から1に増加。
JVMが起動してから 19.103 秒後に、Archive 領域で使用されているリージョン数は0から0で変化なし。
JVMが起動してから 19.103 秒後に、Humongous 領域で使用されているリージョン数は3から3で変化なし。
JVMが起動してから 19.103 秒後に、New領域を対象とするGC が発生。
ヒープ領域の使用量がGCにより26Mから10Mに縮小(ヒープ領域の容量は254M)。
GC処理に22.107 ミリ秒かかった (Pause が付いている場合は、STW時間)。
GC処理期間中に、GC処理が使用したCPU時間は0.00秒。
GC処理期間中に、システム(OS)が使用したCPU時間は0.00秒。
GC処理にかかった実時間は0.02秒。

ログローテ―ト設定

filecount(世代数)=5 filesize(ファイルサイズ)=20M がデフォルト設定。未指定だとデフォルト値が自動で適用される。
ログローテ―トを設定することにより、JVM再起動によるGCログ上書き前にログの退避を行うことができる。
ログローテートを使用したくない場合は、filesize を0 に設定することでログローテート機能が無効化される。

G1GC とは？

• Garbage Frist Garbage Collection の略称
• Java 9以降、G1GCがデフォルト
• 大容量メモリ搭載・マルチプロセッサマシンを対象
• 世代別GC (New世代／Old世代に分ける) の概念が導入されている
• ヒープをリージョンに分割 (ヒープサイズに合わせて2048程度に分割) して管理
• マーキングを付けてガーベジでいっぱいとなったリージョンを優先的に開放
• G1GC で発生するGCには以下の3種類が存在
  １．YoungGC ２．MixedGC ３．FullGC
• GC処理は、Concurrent Marking（CM）とEvacuation (退避) から構成
• Concurrent Marking（CM)は、①並列ルートリージョンスキャン (Concurrent Root Region Scan) ②並列マーク付け(concurrent-mark) ③ 再マーク(remark) ④ クリーンアップ(cleanup) ⑤ 並列クリーンアップ(concurrent-cleanup) のフェーズに分割される。Concurrent が付く処理は、アプリケーションスレッドと並行実行。STWは③と④で発生。
• Evacuation (退避) は、①回収集合選択 ②ルート退避 ③退避の3つで、いずれもSTWが発生。

YoungGC

YoungGCにはYoungGC(normal)とYoungGC中にマーキングをするYoungGC(initial-mark)がある。YoungGCは、New領域に割り当てたリージョンに空きがなくなると発生する。YoungGCでは使用中のオブジェクトはSurvivor領域に割り当てたリージョンに移動し，使用済みのオブジェクトはリージョンごと解放する。また，SerialGCのCopyGCと同様，YoungGC発生時に使用中のオブジェクトはSurvivor領域に割り当てたリージョン間を移動し続け，ある一定の回数を移動するとTenured領域に割り当てたリージョンに移動する。

MixedGC

MixedGCはTenured領域の使用率が増加すると発生する。MixedGCではNew領域に割り当てたリージョンに加えて，目標停止時間内に収まる範囲で，一部のTenured領域に割り当てたリージョンをGCの対象とする。この一部のTenured領域に割り当てたリージョンは，アプリケーションと並行して実行しているオブジェクトが使用中かどうかの解析情報に基づき，解放されるサイズが大きいと予測されるリージョンから優先してGCの対象とする。

FullGC

Javaヒープ内のリージョンに空きがなくなり，MixedGCが発生しない場合，Javaヒープ全体を対象としてFullGCが発生する。SerialGCのFullGCと同様の処理が実施される。

チューニングパラメータ

G1GCで使用可能なJavaオプション

参考資料

1. javaの拡張ランタイム・オプション - Oracle Help Center
2. Unified JVM Logging - SlideShare
3. openjdkのソースコード
4. 3分で理解するG1ガベージコレクション
5. 【Java】G1GC
6. “Stop the World”を防ぐコンカレントGCとは？
7. Javaガベージコレクション - ソフトウェアエンジニアリング
8. Cosminexus V9 アプリケーションサーバ システム設計ガイド(7.15　G1GCの仕組み)
9. 作って学ぶガベージコレクタをやってみた