TT Lab
はじめる
学ぶ 学習パス コース

ヒープは余っていたのにサービスが止まった

GC 停止はヒープ使用量グラフには映らない

TT Labで続きを見る

一言でいうと

JVMヒープは短命なオブジェクト(Young)と長命なオブジェクト(Old)を分けて管理します。GCログ(-Xlog:gc)には、その整理がいつ、どれだけの間アプリケーションを止めたかが1行ずつ記録されます。サービスが遅くなったとき、最初に開くべきなのがこのログです。

なぜ必要なのか

「ヒープは余っているのにサービスが止まった」というこのコースのタイトルは、実際には2種類の事件を指しています。1つはこのモジュールの事件で、ヒープ使用量のグラフは60%なのに、応答時間が突然3秒ずつ跳ね上がります。原因はGCの停止(pause)でした。整理すべきものが増えると、JVMはアプリケーションのスレッドをすべて止めて(stop-the-world)クリーンアップします。ヒープが余っていることと、クリーンアップが速いことは別の話です。もう1つは次のモジュールの事件で、ヒープもGCも問題ないのに、スレッドがすべて詰まっています。この2つを見分ける最初の道具がGCログです。ログに長い停止がなければ、犯人はGCではありません。

このコースがJVMを扱うのは、韓国市場の需要があるからです。2026-09-11の求人集計では、Javaは全体160件(16.7%)ですが、韓国の6社では108件(38.0%)で、海外(8.3%)の4倍を超えました。求人が「JVMチューニング経験」「障害分析」と書くとき、その意味するところはこのモジュールから始まります。

どう動くのか

ヒープサイズはjavaコマンドのドキュメントにある-Xms(初期・最小)と-Xmx(最大)で決めます。ドキュメントには、サーバーのデプロイでは両方を同じ値にするのが一般的だと書かれています。起動後にヒープが拡張されることで発生するGCを避けるためです。値を指定しない場合は、システム構成に応じて実行時に決まります。そのルールが-XX:MaxRAMPercentage(デフォルトは25%)と-XX:InitialRAMPercentage(デフォルトは1.5625%)です。つまり、メモリ8GBのマシンで何も指定しなければ、最大ヒープは2GBになります。コンテナでは、この「マシンのメモリ」がcgroupの上限として読み取られます(モジュール4で実際に測ります)。

コレクターは利用可能なコレクターのドキュメントが3つに分けて説明しています。Serialはスレッド1つですべてのGCを実行し、スレッド間の通信コストがないため、小さなデータ(ドキュメントでは約100MBまでとされています)に向いています。-XX:+UseSerialGCで有効にします。Parallelはスループット(throughput)重視のコレクターで、複数のスレッドでGCを分担します。G1は作業の大部分をアプリケーションと並行して(mostly concurrent)実行するコレクターで、停止時間の目標を高い確率で満たしつつスループットも維持するよう設計されており、サーバー級のマシンではデフォルトです。どれが良いかに正解はなく、同じ負荷で動かして停止時間を測るのが答えです。ラボでもそのように測ります。

ログは統合ログ-Xlogで有効にします。ドキュメントの変換表には、旧PrintGCDetailsが-Xlog:gc*に当たると書かれています。-Xlog:gc:file=gc.logはGCイベントを1行ずつ、-Xlog:gc*:file=gc.logは段階ごとの詳細までファイルに残します。実際の出力は次のようになります(JDK 21、実測)。

[0.002s][info][gc] Using G1
[0.029s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 16M->4M(32M) 1.683ms
[0.030s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 19M->4M(32M) 1.005ms

読み方です。角括弧はJVM起動後の経過時間、GC(0)はGC番号、Pause Youngは若い世代の停止、16M->4M(32M)は整理前→整理後(ヒープ全体)で、最後が停止時間です。-Xlog:gc*を有効にすると、冒頭にHeap Max Capacity: 64Mのような初期化情報が付き、1回の停止が[gc,start]と[gc]の2行に分かれます。Full GCはPause Fullと出力されます。これが頻繁に見えるなら、Old領域が埋まり続けているということで、リークかヒープが小さいかのどちらかです。

稼働中のプロセスはjstatで見ます。jstat -gc <pid> 1000 5は1秒間隔で5回ヒープ統計を出力します。列名はドキュメントで決まっています。S0C/S1Cはサバイバー領域の容量、EC/EUはEdenの容量・使用量、OC/OUはOldの容量・使用量、YGC/YGCTはYoung GCの回数・時間、FGC/FGCTはFull GCの回数・時間、GCTはGCの合計時間です。YGCが毎秒数十ずつ増えるなら割り当てが多すぎ、FGCが増えるならOldが埋まっています。

jcmdは、同じマシン上で同じユーザーで起動したJVMに診断コマンドを送ります。jcmd -lがJVMの一覧を、jcmd <pid> GC.heap_infoがヒープの概要を、jcmd <pid> VM.flagsが実際に適用されたフラグ(-XX:MaxHeapSize=を含む)を返します。「設定ファイルには4gと書いたのに」と「JVMが実際に使っている値」が違うとき、VM.flagsが判定します。

現場での姿

最も多いのは、ログをそもそも有効にしていないサービスです。障害が起きてから有効にすることはできません。2つ目は-Xmxをマシンのメモリ全部にしてしまうことです。JVMはヒープの外にもメタスペース・スレッドスタック・コードキャッシュ・ダイレクトバッファーを使うため、ヒープがマシンのメモリに達すると、OSがプロセスを強制終了します。3つ目は停止時間を平均で見ることです。平均5msの陰に、800msのFull GCが1日3回隠れています。最大値と分布を見る必要があります。ラボでログから最大停止時間を取り出すのはそのためです。

次のラボですること

/opt/lab/fixtures/jvm/Churn.javaをコンパイルして-Xlog:gcでログを作り、-Xlog:gc*の詳細ログからYoung停止の数を数え、-Xmx64mと-Xmx256mの停止回数を比較し、最大停止時間を取り出し、jstat -gcで稼働中のプロセスを観察し、SerialとG1を同じ負荷で比べ、jcmdでヒープ情報と実際のフラグを取得します。