公開日:2/5/2021  更新日:6/13/2021

  • twitter
  • facebook
  • line

【G1GC】Xlog オプションでGCログを出力した話

はじめに

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

1.OS
Windows10
2.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種類が存在
    1.YoungGC 2.MixedGC 3.FullGC
  • GC処理は、Concurrent Marking(CM)とEvacuation (退避) から構成
  • Concurrent Marking(CM)は、①並列ルートリージョンスキャン (Concurrent Root Region Scan) ②並列マーク付け(concurrent-mark) ③ 再マーク(remark) ④ クリーンアップ(cleanup) ⑤ 並列クリーンアップ(concurrent-cleanup) のフェーズに分割される。Concurrent が付く処理は、アプリケーションスレッドと並行実行。STWは③と④で発生。
  • Evacuation (退避) は、①回収集合選択 ②ルート退避 ③退避の3つで、いずれもSTWが発生。

リージョン

Fig. 分割されたリージョン [E:Eden領域 S:Survivor領域 O:Old(Tenured)領域)]

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と同様の処理が実施される。

各GCの対象ヒープ領域

Fig. 各GCの対象ヒープ領域

チューニングパラメータ

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

オプション 説明
XX:MaxGCPauseMillis 目標停止時間をミリ秒単位で設定。一時停止予測モデルの予測に基づいてリージョン数を調整してくれる。デフォルト値は200ms。
Xmx ヒープ領域の最大サイズを設定。
Xms ヒープ領域の初期サイズを設定(-Xmxオプションと同じ値の設定を推奨)。
XX:MaxMetaspaceSize Metaspace領域の最大サイズを設定。
XX:MetaspaceSize Metaspace領域に起因するFullGCの基準値を設定。アプリケーションで必要なクラス情報のサイズから見積もった値を設定。-XX:MaxMetaspaceSizeオプションと同じ値の設定を推奨。
XX:SurvivorRatio New領域に対するSurvivor領域が最大サイズの場合の割合を設定。
XX:ParallelGCThreads YoungGCおよびMixedGCを行うスレッド数を設定。デフォルト値は、OSが認識しているCPU数。
XX:ConcGCThreads アプリケーションと並行して処理を実行するスレッド数を設定。

参考資料

  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. 作って学ぶガベージコレクタをやってみた

戻る