Claude CodeでJavaのGCログを解析する — 停止時間とヒープの見直し点

JavaのGCログは、そのまま丸ごと貼ると読ませたい行が埋もれます。実際に手元で-Xlog:gc*を付けて動かしたところ、GCがわずか6回の短いプログラムでも114行が出ました。向いているのは、Pause行だけを抜き出して要約し、その要約をClaude Codeに渡して見直し案を出させるやり方です。

この記事では、-Xlog:gcのログを取る設定、Pauseの頻度と長さ・ヒープ使用量を抜き出す小さなスクリプト、claude -pに渡すプロンプトの形、返ってきた案を負荷試験で確かめる手順を順に示します。サンプルのログは、Corretto 17.0.3(OpenJDK 17.0.3)で小さなプログラムを動かして取ったものです。本番のログではなく、行の形を確かめるための例です。

取るログは-Xlog:gcの1行と、-Xlog:gc*の全部で性格が違う

GCログの設定は-Xlogで行います。JEP 271によれば、-Xlog:gcは旧来の-XX:+PrintGCに近く、GC1回につき1行を出す設計です。-Xlog:gc*のようにワイルドカードを付けると、gcタグを含む全タグが対象になります。

出力先とローテーションも同じオプションで決まります。Oracleのjavaコマンドのリファレンスでは、file=でファイルに出し、ファイル名の%pはJVMのPID、%tは起動時刻に置き換わると説明されています。サイズでのローテーションはfilesize=10M,filecount=5のように指定します。旧オプションの-Xloggc:filenameは-Xlog:gc:filenameに置き換えられています。

java -Xms64m -Xmx64m \
  '-Xlog:gc:file=gc-%t.log:uptime,level,tags' \
  Churn

デコレーターを省くと既定はuptime・level・tagsです。ここでは明示して、経過秒を各行の先頭に残しています。負荷試験を何度も回すので、%tで実行ごとにファイルを分けておくと、あとで取り違えません。

実際に出た-Xlog:gcの行は次の形でした。

[0.006s][info][gc] Using G1
[0.023s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 23M->3M(64M) 0.634ms
[0.027s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 38M->6M(64M) 1.148ms

23M->3M(64M)は、GC前のヒープ使用量、GC後の使用量、ヒープ全体の容量です。末尾の0.634msがその回の停止時間です。

-Xlog:gc*に切り替えると、同じ1回のGCが十数行に増えます。gc,phasesにはEvacuate Collection Setなどの内訳、gc,heapにはリージョン数、gc,cpuにはUser・Sys・Realが出ます。起動直後にはgc,initとしてCPU数やメモリ量の行も並びます。内訳を調べる段階では役に立ちますが、最初の一次切り分けに渡す入力としては重すぎます。

Pauseの頻度と長さ、GC後の使用量を抜き出す

ログ全文を渡すかわりに、1回ごとの経過秒・ヒープの前後・停止時間を並べた表と、停止時間の件数・平均・最大だけを渡します。次のスクリプトは、上のサンプルと同じ形式の行を前提にしたものです。

#!/bin/sh
# usage: gc-digest.sh gc.log
awk '
/Pause/ {
  split($0, t, "]"); up = substr(t[1], 2) + 0
  n++; ms = $NF; sub(/ms$/, "", ms); ms += 0
  match($0, /[0-9]+M->[0-9]+M\([0-9]+M\)/)
  heap = substr($0, RSTART, RLENGTH)
  split(heap, h, "->")
  after = h[2] + 0
  sum += ms; if (ms > max) max = ms
  printf "%s\t%s\tafter=%dM\t%.3fms\n", up, heap, after, ms
}
END { printf "pauses=%d mean=%.3fms max=%.3fms\n", n, sum/n, max }' "$1"

サンプルのログに掛けた結果です。

0.023	23M->3M(64M)	after=3M	0.634ms
0.027	38M->6M(64M)	after=6M	1.148ms
0.03	39M->9M(64M)	after=9M	1.177ms
0.031	43M->12M(64M)	after=12M	0.709ms
0.033	44M->16M(64M)	after=16M	0.698ms
0.035	45M->18M(64M)	after=18M	0.759ms
pauses=6 mean=0.854ms max=1.177ms

この例では、GC後の使用量が3→6→9→12→16→18と回ごとに増えています。生き残るデータが積み上がっていく形で、これはafterの列を並べて初めて見える情報です。停止時間は最大でも1.2msほどで、停止の長さよりヒープの底上げのほうが気になる、という読み方になります。

このスクリプトで手元で確かめたのは、G1のPause Young行だけです。JEP 271は、既存のGCログパーサーが新しい形式でそのまま動くことを目標にしていません。Full GCや別のコレクターでは行の形が違う可能性があるので、本番のログで動かす前に、Pauseを含む行を数行目で見比べておきます。

claude -pにパイプで渡して、見直し案を出させる

Claude Codeの非対話モードは標準入力を読めます。ドキュメントの例は、ビルドログをcat build-error.txt | claude -p '…'のようにパイプで渡す形です。同じ形でスクリプトの出力を渡します。

./gc-digest.sh gc-20261027.log | claude --bare -p \
  'JavaのGCログの要約です。G1、-Xms=-Xmx=64m。
   1) 停止時間の傾向 2) GC後の使用量の推移
   3) 見直し候補を、根拠となる行と、確かめる指標を付けて挙げてください。
   ログにない原因は推測と明記してください。'

--bareを付けると、フック・プラグイン・auto memory・CLAUDE.mdを読み込まずに起動します。ドキュメントはスクリプト実行でこれを勧めています。ただし--bareではサブスクリプションのログインを使わないので、ANTHROPIC_API_KEYを環境変数に設定してから実行します。

要約のほかに、プロンプトへ添えておきたい前提があります。使っているコレクターは、ログの先頭のUsing G1の行で分かります。有効な値はjava -XX:+PrintFlagsFinal -versionで確かめられ、手元の17.0.3ではMaxGCPauseMillisが200、UseG1GCがtrueでJVMが環境から自動で選んだ値と表示されました。これにコンテナのメモリ制限と、試験した負荷の条件を加えます。

標準入力の上限は10MBで、超えるとエラーで終了します。要約を渡す限り問題になりませんが、生ログを直接渡す運用にするとここに当たります。大きな入力は、ファイルに書き出してパスを指定する形がドキュメントの案内です。

夜間のジョブなどで人が許可を答えられないときは、--permission-prompts noneを付けると、許可が要る操作は拒否されて実行が続きます。このフラグはv2.1.259以降で使えます。パイプで渡すだけなら、Claudeにファイルを読ませる権限は要りません。

定期実行で繰り返し回す場合の消費量は、claude -pが5時間枠を多く消費する報告で切り分け方を扱っています。

返ってきた案は仮説として読み、触る前に指標を決める

Claudeの回答は、ログから言える範囲と、ログの外の推測が混ざります。プロンプトで「推測と明記」を求めたのはそのためです。出てきそうな候補ごとに、ログから言えることと言えないことを分けます。

MaxGCPauseMillisはGCの停止時間の目標値で、Oracleのリファレンスは「ソフトな目標で、JVMはベストエフォートで達成を試みる」と書いています。G1の既定は200ミリ秒です。目標を下げれば必ず停止が短くなるわけではない、という含みになります。

-Xmsと-Xmxは、サーバー用途では同じ値にすることが多いとされています。ヒープの上限を変えるときは、コンテナのメモリ制限とあわせて見る必要があります。この点はGCログには出ません。

GC後の使用量が右肩上がりのとき、ログだけでは「容量が足りない」のか「解放されないオブジェクトがある」のかを区別できません。ヒープの中身を見るには、ヒープダンプなど別の入力が要ります。

再起動できない本番では、jcmdでログを有効にする

起動オプションに-Xlogを入れ忘れたJVMでも、再起動せずにログを取り始められます。JEP 271とOracleのリファレンスは、統合ログの設定をjcmdで実行中に変えられると説明しています。コマンドはVM.logです。

jcmd <PID> VM.log what=gc output=live.log decorators=uptime,level,tags
jcmd <PID> VM.log disable

手元で-Xmx64mのプログラムに対して実行したところ、有効にした後のGCからlive.logに次の形の行が書かれました。

[3.868s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 23M->6M(64M) 2.447ms

有効にする前のGCは記録されません。現象が出ている最中に取り始めると、その後の分だけが手に入ります。VM.log listで現在の出力設定を確かめられ、VM.log disableで止められます。

ファイルが大きくなる環境では、filesizeとfilecountを付けたローテーションに加え、書き込みで本体の処理を止めたくないときは-Xlog:asyncも選べます。非同期モードでは、ログ行がバッファに積まれ別スレッドが書き出します。バッファがあふれると行は捨てられるので、停止時間の件数を数えるときは、欠けた行がないかも意識しておきます。

負荷試験で1つずつ確かめる

見直し案を本番に入れる前に、同じ負荷で変更前後のログを取り、同じスクリプトに掛けて比べます。変えるのは1回に1項目です。

比べるときにClaudeに頼めるのは、2つの要約の差を言葉にすることです。採るかどうかは、アプリの応答時間という別の指標を見て人が決めます。

ログを渡す前に外すもの

渡した内容は会話に載ります。-Xlog:gc*にはgc,initのCPU数やメモリ量の行が含まれ、hostnameデコレーターを付ければホスト名も各行に入ります。要約だけを渡す構成なら、こうした環境情報は最初から外れます。

Claude Codeに渡したデータの扱いはClaude Codeのデータは学習に使われるかにまとめています。装置のログCSVをスクリプトで要約させる同じ考え方の手順は、PLCのログ解析にもあります。全体像はClaude Codeの完全ガイドから辿れます。