GC ログを読む

目標

小さなJavaプログラムで実際のGCログを作って読みます。停止回数・停止時間・ヒープサイズの影響・コレクターの比較・jstat・jcmdを扱います。

なぜ重要なのか

「サービスが遅い」と報告を受けたとき、最初の分かれ道はGCかどうかです。GCログに長い停止がなければ、犯人は別の場所(ロック・プール枯渇)です。ログの有効化の仕方と読み方、そしてヒープサイズとコレクターが停止にどう影響するかを、実際の数字で確認します。用意されたChurn.javaはjava Churn <초> <유지MB> [반복당KB](プレースホルダーは秒数、保持するMB、反復あたりのKBです)で動き、保持するMBの分は持ち続け、残りは捨て続けます。

ステップ

1. mkdir -p /root/jvm/gc && cd /root/jvm/gc && javac -d . /opt/lab/fixtures/jvm/Churn.javaでコンパイルしてください。/root/jvm/gc/Churn.classが作られ、java -cp /root/jvm/gc Churn 1 0がdoneを出力します。
2. java -Xmx256m -Xlog:gc:file=/root/jvm/gc/gc.log -cp /root/jvm/gc Churn 5 24でGCログを作ってください。ログにはUsingで始まるコレクターの行とPause Youngの行が必要です。
3. -Xlog:gc*:file=/root/jvm/gc/gc-detail.logで詳細ログを作ってください(同じ負荷で5秒・24MB)。Pause Youngを含みmsで終わる行(停止の完了行)の数を数え、/root/jvm/gc/answer.txtにyoung_pauses=<n>の1行で書いてください。
4. 同じ負荷を-Xms64m -Xmx64mで実行して/root/jvm/gc/gc-64.log(-Xlog:gc*)を、-Xmx256mで実行して/root/jvm/gc/gc-256.logを作り、/root/jvm/gc/compare.txtにxmx64_pauses=<n>とxmx256_pauses=<n>の2行(ステップ3と同じ数え方)を書いてください。64M側のほうが多くなる必要があります。
5. gc-256.logから最も長い停止(Pause行の末尾のms値)を探し、/root/jvm/gc/pause.txtにmax_pause_ms=<x>で書いてください(小数第3位まで、ログの値のまま)。
6. java -Xmx128m -cp /root/jvm/gc Churn 12 24をバックグラウンドで起動し、jstat -gc <pid> 1000 5 > /root/jvm/gc/jstat.txtで1秒間隔5回の出力を残してください。ヘッダー(S0C・EC・YGC・FGC…)とデータ5行が必要です。
7. -XX:+UseSerialGC -Xlog:gc:file=/root/jvm/gc/gc-serial.logと-XX:+UseG1GC -Xlog:gc:file=/root/jvm/gc/gc-g1.logで同じ負荷(-Xmx128m、5秒・24MB)を実行し、それぞれの最大停止時間を/root/jvm/gc/collector.txtにserial_max_pause_ms=<x>とg1_max_pause_ms=<x>の2行で書いてください。
8. Churnを再びバックグラウンドで起動したまま、jcmd <pid> GC.heap_info > /root/jvm/gc/heap_info.txtとjcmd <pid> VM.flags > /root/jvm/gc/vm_flags.txtを残してください。heap_infoにはtotalとusedが、vm_flagsには-XX:MaxHeapSize=が含まれている必要があります。

参考

• 最大停止時間の取り出し: awk '/Pause/ && match($0,/[0-9.]+ms$/){v=substr($0,RSTART,RLENGTH-2)+0; if(v>m)m=v} END{print m}' gc-256.log
• バックグラウンドのpid: java ... & PID=$!のあとにjstat -gc $PID 1000 5を実行します。プログラムは自分で終了します。
• よくあるミス: -Xlog:gc*でPause Youngを数えると、開始行と完了行の両方が拾われます。msで終わる行だけを数えてください。

教材をコンパイルする

/root/jvm/gcにChurn.javaをコンパイルしてChurn.classを作成してください。java -cp /root/jvm/gc Churn 1 0がdoneを出力します。

javac -d <出力ディレクトリ> <ソース>です。クラスにはパッケージがないので、-cpにはディレクトリだけを渡せば済みます。

GCログを有効にする

-Xmx256m -Xlog:gc:file=/root/jvm/gc/gc.logでChurn 5 24を実行してください。ログにはUsingの行とPause Youngの行が必要です。

-Xlog:gc:file=<パス>がGCイベントをファイルに出力します。最初の行が、どのコレクターを使っているかを教えてくれます。

詳細ログで停止を数える

-Xlog:gc*:file=/root/jvm/gc/gc-detail.logで同じ負荷を実行し、Pause Youngを含みmsで終わる行の数を/root/jvm/gc/answer.txtにyoung_pauses=で書いてください。

gc*は1回の停止を[gc,start]と[gc]の2行で残します。完了行だけを数えるには、msで終わる行を選んでください: grep -E 'Pause Young.*ms$' | wc -l

ヒープが小さいと停止が増える

-Xms64m -Xmx64mでgc-64.logを、-Xmx256mでgc-256.logを(どちらも-Xlog:gc*)作り、compare.txtにxmx64_pauses=とxmx256_pauses=を書いてください。64M側のほうが多くなる必要があります。

同じ割り当て量を小さいヒープに入れるとEdenがすぐに埋まり、Young GCが頻繁になります。数え方はステップ3と同じです。

平均ではなく最大停止

gc-256.logのPause行の末尾のms値のうち最大値を/root/jvm/gc/pause.txtにmax_pause_ms=で書いてください。

「参考」セクションのawkの1行で最大値を取り出せます。値はログの小数第3位までそのままです。

稼働中のプロセスをjstatで見る

Churn 12 24 (-Xmx128m)をバックグラウンドで起動し、jstat -gc 1000 5 > /root/jvm/gc/jstat.txtを残してください。ヘッダーとデータ5行が必要です。

java ... & PID=$!でpidを取得し、jstat -gc $PID 1000 5を実行します。プログラムは12秒後に自分で終了するので、その間に5回出力します。

SerialとG1を同じ負荷で比べる

-XX:+UseSerialGCでgc-serial.logを、-XX:+UseG1GCでgc-g1.logを(-Xmx128m、-Xlog:gc、Churn 5 24)作り、collector.txtにserial_max_pause_ms=とg1_max_pause_ms=を書いてください。

各ログの最初の行はUsing SerialまたはUsing G1になっている必要があります。最大停止時間は、ステップ5のawkをファイルだけ変えて使います。

jcmdでヒープ情報と実際のフラグを取得する

Churnをバックグラウンドで起動したまま、jcmd GC.heap_info > /root/jvm/gc/heap_info.txtとjcmd VM.flags > /root/jvm/gc/vm_flags.txtを残してください。

jcmd -lでpidを確認できます。VM.flagsはJVMが実際に適用した値(-XX:MaxHeapSize=…)を表示します。設定ファイルではなく、これが真実です。