Claude CodeでJavaのJFRを読む — ホットメソッドとGC・ロック待ちの切り分け

JFR(Flight Recorder)の記録は、そのままではClaude Codeに渡せません。実際に15秒だけ記録したファイルをテキストにすると約15.6MB、--jsonでは約73MBになりました。向いているのは、jfrコマンドでイベントの種類を絞り、jqで集計した数百バイトの要約だけを渡すやり方です。

この記事では、JFRの記録の取り方、jfr summaryで全体を眺める手順、CPU・GC・ロック待ち・アロケーションをそれぞれ絞るコマンド、Claude Codeに渡すプロンプトの形、結果の読み分け方を順に示します。サンプルはCorretto 17.0.3(OpenJDK 17.0.3)で小さなプログラムを動かして取った出力です。本番の記録ではなく、出力の形と絞り方を示すための例です。

GCログだけを調べたいときはGCログの解析手順、スレッドの停止位置を調べたいときはjstackのスレッドダンプ解析が入り口になります。JFRはその両方を1つの記録に含められるのが特徴です。

記録は.jfrのバイナリで、読む前に絞る必要がある

JFRのファイルはバイナリ形式です。jfrコマンドは、バイナリの記録を人が読める形に変換し、フィルタし、要約するためのツールです。つまりClaude Codeに.jfrを読ませるのではなく、jfrコマンドの出力を読ませる構成になります。

手元で動かした記録の大きさは次のとおりでした。

イベントを1種類に絞るだけで桁が変わります。それでもJSONは、1フレームごとにクラスローダーやモジュール情報まで入れ子で出すので、絞った後でも大きく見えます。Claude Codeに渡す前に、jqで必要な項目だけを集計するのが現実的です。

記録を取る — StartFlightRecordingとjcmd

JFRの記録は、起動時に-XX:StartFlightRecordingを付けるか、動いているJVMにjcmdでJFR.startを送って始めます。起動オプション側にはfilename・duration・settings・maxage・maxsize・dumponexitなどを指定できます。

java -XX:StartFlightRecording=filename=rec.jfr,settings=profile \
  -Xmx256m Work

settingsを省くと、JDK付属のdefault.jfcが使われます。既定の設定は低オーバーヘッドで常時の記録にも向きます。profile.jfcは情報が多い代わりにオーバーヘッドが大きく、短時間の記録向けです。性能問題を追うときは、再現できる負荷をかけながらsettings=profileで数十秒〜数分だけ取る使い分けになります。

動いているプロセスに後から付けるなら、jcmd <pid> JFR.startで始め、JFR.dumpで書き出します。durationを付けておけば、指定時間で記録が止まります。

jfr summaryで、何が記録されたかを先に数える

記録が取れたら、まずjfr summaryを実行します。jfr summaryは、記録されたイベントの種類ごとに件数とディスク上の大きさを出します。

jfr summary rec.jfr | head -20

手元の記録では、先頭は次のようになりました(抜粋)。

 Version: 2.1
 Chunks: 1
 Start: 2026-10-28 02:57:53 (UTC)
 Duration: 15 s
 
 Event Type                                   Count  Size (bytes)
==================================================================
 jdk.GCPhaseParallel                          55841       1393749
 jdk.ObjectAllocationSample                    4272         61459
 jdk.JavaMonitorEnter                          1429         30009
 jdk.GarbageCollection                          116          2213
 jdk.ExecutionSample                             20           200

ここで読み取れることが2つあります。1つ目は、どのイベントが記録されているかです。jdk.JavaMonitorEnterが1,429件あるので、ロック競合の候補があります。jdk.GarbageCollectionは116件で、15秒で116回のGCが起きています。2つ目は、イベントの数そのものです。jdk.ExecutionSampleは20件しかなく、CPUの手がかりは薄い記録だと分かります。件数が少ないイベントを根拠に結論を出さないための、最初の確認になります。

もう1つ、この一覧にはjdk.InitialEnvironmentVariable(62件)やjdk.SystemProcess(895件)のような、環境変数やプロセス一覧を含むイベントも並んでいます。記録を丸ごと外部に渡すと、環境変数の値が含まれる可能性があります。次の節のようにイベントを指定して出力すれば、必要な種類だけを取り出せます。

CPU・GC・ロック待ち・アロケーションを絞る4本のコマンド

jfr printは--eventsにイベント名、--categoriesにカテゴリ名を取り、--jsonか--xmlで機械処理向けの出力になります。スタックトレースは既定で5フレームまでで、--stack-depthで変えられます。

次のシェルスクリプトは、4種類のイベントをそれぞれjqで集計して、数行の要約にします。

#!/bin/sh
# usage: jfr-digest.sh recording.jfr AppClassName
f=$1; app=$2
echo "## CPU: sampled top frames"
jfr print --json --events jdk.ExecutionSample --stack-depth 1 "$f" |
  jq -r '.recording.events[].values.stackTrace.frames[0]
         | "\(.method.type.name).\(.method.name):\(.lineNumber)"' |
  sort | uniq -c | sort -rn | head -5
echo "## GC: pause total / max (s)"
jfr print --json --events jdk.GarbageCollection "$f" |
  jq -r '[.recording.events[].values.sumOfPauses
          |ltrimstr("PT")|rtrimstr("S")|tonumber]
         | "count=\(length) total=\(add) max=\(max)"'
echo "## Lock: JavaMonitorEnter by top app frame"
jfr print --json --events jdk.JavaMonitorEnter --stack-depth 8 "$f" |
  jq -r --arg app "$app" '.recording.events[].values
    | [(.stackTrace.frames|map(select(.method.type.name==$app))
        |first|.method.name // "?"),
       (.duration|ltrimstr("PT")|rtrimstr("S")|tonumber)] | @tsv' |
  awk -F'\t' '{n[$1]++; s[$1]+=$2}
    END{for(k in n)printf "%s\tevents=%d\twait=%.1fs\n",k,n[k],s[k]}'
echo "## Allocation: sampled weight by top app frame"
jfr print --json --events jdk.ObjectAllocationSample --stack-depth 8 "$f" |
  jq -r --arg app "$app" '.recording.events[].values
    | [(.stackTrace.frames|map(select(.method.type.name==$app))
        |first|.method.name // "(jdk)"), .weight] | @tsv' |
  awk -F'\t' '{n[$1]++; s[$1]+=$2}
    END{for(k in n)printf "%s\tsamples=%d\tweight=%.1fGB\n",k,n[k],s[k]/1e9}' |
  sort -t= -k3 -rn

アロケーションとロックでは、--stack-depth 8にしてアプリ側のクラス名を持つ最初のフレームを探しています。深さ1のままだと、先頭はStringBuilderやallocateUninitializedArrayのようなJDK内部のフレームばかりになり、どのアプリのメソッドが原因か分かりません。実際に深さ1で集計したところ、上位はallocateUninitializedArrayとnewStringでした。

実行した結果は次の453バイトです。

./jfr-digest.sh rec.jfr Work

## CPU: sampled top frames
  15 Work.slowMath:16
   2 jdk/jfr/internal/PlatformRecorder.periodicTask:499
   2 Work.buildReport:10
   1 jdk/jfr/internal/RequestEngine.run_requests:241
## GC: pause total / max (s)
count=116 total=0.11568367300000001 max=0.027685458
## Lock: JavaMonitorEnter by top app frame
locked	events=1429	wait=37.5s
## Allocation: sampled weight by top app frame
buildReport	samples=4235	weight=18.0GB
(jdk)	samples=37	weight=0.0GB

73MBのJSONが、これだけの要約になりました。サンプルのプログラムは、4スレッドが15秒間、文字列連結(buildReport)、平方根と三角関数の計算(slowMath)、synchronizedの中で5ミリ秒眠る処理(locked)を繰り返す構成です。要約はその構造をそのまま映しています。

Claude Codeに渡すプロンプト

要約ができたら、標準入力でclaude -pに渡します。claude -pは標準入力と標準出力をUnixのツールと同じようにつなげます。common workflowsの「Pipe Claude into scripts」と同じ使い方です。

./jfr-digest.sh rec.jfr Work | claude --bare -p \
  "JFRの要約です。CPU・GC・ロック待ち・アロケーションのうち、
どれが遅さの主因かを、数字を引用して順位づけしてください。
根拠が足りない項目は、足りない理由と追加で取るべきイベント名を書いてください。
ソースは読まず、要約だけで判断してください。" \
  --output-format json

--bareは、スクリプトからの呼び出しでフック・スキル・MCPサーバー・CLAUDE.mdの自動読み込みを省くオプションです。スクリプトやSDKから呼ぶときの推奨モードで、普段の開発セッションの設定を引きずらず、同じ入力に同じ条件で答えさせたいときに向きます。

ただし--bareはサブスクリプションのログイン情報を読みません。ANTHROPIC_API_KEYを環境変数に設定した状態で使います。ProやMaxのログインだけで使っている場合は、--bareを外せば普段のログインで動きます。その代わりCLAUDE.mdやフックも読み込まれるので、答えの条件は環境ごとに少し変わります。

プロンプトのポイントは3つです。

• 数字を引用させる。「ロック待ちが37.5秒」のように、要約のどの行を根拠にしたか分かる形で答えさせます。
• 根拠不足を許す。20件しかないCPUサンプルから断定させないために、「足りない項目は足りないと書く」を明示します。
• ソースを読ませない段階を作る。最初は要約だけで原因の候補を絞らせ、次の段階でメソッドのソースを渡すと、推測が混ざりにくくなります。

返ってきた分析は、あくまで仮説です。この仮説は、次の節の切り分けに沿って自分で確かめます。

要約からの切り分け — CPU・GC・ロックのどれが主因か

サンプルの数字を、4つの観点で読み分けます。

GCの停止は、116回で合計0.116秒です。15秒の実行時間に対して1%に満たず、GCチューニングで取れる余地は小さい記録です。ところがGCの回数自体は多く、その理由はアロケーションの表にあります。buildReportの文字列連結が、サンプル上の割当量の大半を占めています。GCそのものを調整する前に、連結をStringBuilderに置き換えるといった割当元の見直しが先に来ます。

ロック待ちは、4スレッドがsynchronizedの中で5ミリ秒眠る構成なので、待ちが積み上がるのは当然です。実際のサービスでは、ロックを保持する時間と、保持中に何をしているか(I/Oや外部呼び出しがないか)を見るのが次の一手になります。jdk.JavaMonitorEnterのイベントには、待たされたスレッドだけでなく、直前にロックを持っていたスレッド(previousOwner)も記録されます。誰が持っているかを辿るには、この項目を足して集計します。

CPUの欄は、サンプル数が20件と少ないので参考値にとどめます。ここはjdk.ExecutionSampleの記録間隔を短くするか、記録時間を延ばして取り直す判断になります。JFRの設定はjfr configureで.jfcファイルを作って調整できます。

つまずきやすい点

次の点も、実際に踏みやすいところです。

• スタックが浅すぎる。jfr printのスタックは既定で5フレームまでなので、アプリのコードがその外にあると原因が見えません。上の例のように--stack-depthを増やし、アプリのクラス名で絞ります。
• サンプルの重さを回数と取り違える。jdk.ObjectAllocationSampleは名前のとおりサンプリングされたイベントです。weightの合計は割当量の目安として読み、実測値と書かないほうが安全です。
• 記録に環境情報が入る。jfr summaryの一覧に環境変数やプロセス一覧のイベントがあるように、記録には実行環境の情報も含まれます。JDK 21のjfrコマンドには、記録から機微な内容を取り除くjfr scrubもあります。ファイルごと共有するなら、--exclude-eventsで該当イベントを外してからにします。
• プロファイル用の設定を常用する。profile.jfcは短時間の調査用です。本番で常時取るなら既定の設定に戻します。

手順をまとめて固定する

同じ手順を繰り返すなら、CLAUDE.mdに要約スクリプトの場所と、渡してよい入力の範囲を書いておきます。設定側では、jfrとjqの実行だけを許可すると、毎回の確認を減らせます。権限ルールはBash(コマンド *)の形で書き、*はサブコマンドの後ろに置きます。

{
  "permissions": {
    "allow": [
      "Bash(jfr summary *)",
      "Bash(jfr print *)",
      "Bash(./jfr-digest.sh *)"
    ]
  }
}

jqは、シェルのパイプの一部として使われます。複合コマンドの扱いは権限の仕様に依存するので、パイプ全体を許可したい場合は、要約スクリプトの1本にまとめておくほうが設定が簡単です。上の例では、jqを呼ぶ部分をjfr-digest.shに閉じ込めています。

要約を渡す前に、含まれる情報が意図したイベントだけかを--eventsの指定で確かめます。Claude Codeの返す提案は、アロケーションの減らし方もロックの分割も、実際のサービスに入れて再計測するまでは仮説です。変更前後で同じ負荷をかけ、同じ要約スクリプトを走らせ、数字が動いたかを見る流れが、JFRの記録と相性の良い進め方です。Java 21へ上げる作業を並行して進めている場合は、OpenRewriteを使った移行の手順の後で取り直した記録と比べると、バージョン差の影響も切り分けられます。

まとめ

JFRは、記録の大きさがClaude Codeに渡すうえでの最大の壁です。15.6MBのテキストや73MBのJSONを渡すかわりに、jfr print --eventsでイベントを絞り、jqで集計して数百バイトにすると、原因の順位づけを依頼できる形になります。その先の判断は、要約の数字を根拠に切り分けます。GCの停止が全体の1%に満たなければGCチューニングは後回しで、割当元を見る。ロック待ちが大きければ保持時間と保持中の処理を見る。CPUサンプルが少なければ記録を取り直す。Claude Codeの答えをそのまま採らず、この切り分けに照らして採否を決めるのが、JFRを読ませるときの実務的な線引きです。