Javaの性能トラブルを防止 ～Javaのガーベジコレクション（GC）ログの見方を知る（シリアルGC / パラレルGC編）～
富士通技術者ブログ～Javaミドルウェア～

1. はじめに

OpenJDKでアプリケーションを実行すると、Java仮想マシン（Java Virtual Machine：以降、JVM）が不要になったオブジェクトをJavaヒープ上から削除し、再度利用可能にするためのガーベジコレクション（以降、GC）が行われます。GCによってJVMはJavaヒープを効率的に利用できますが、GC処理中はアプリケーションの処理が停止するため、GCの長時間化や頻発は性能トラブルに直結します。

GCに関する性能トラブル調査には、GCログが有用です。GCログには、GC処理に費やした時間やGC前後のメモリー使用状況などが出力されるため、これらを分析することでチューニングやアプリケーション修正に役立てることができます。
GCログの出力は、JDK 8とJDK 9で大きく変わりました。これまでフォーマットにばらつきがあったJVMの各種ログの出力が、「JVM統合ロギングフレームワーク」に統合され、GCログも採取方法やフォーマットが変わっています。
今回は、最初にJVM統合ロギングフレームワークを簡単に紹介した後、GCログの採取方法、読み方、分析方法について説明します。なお、GCログの内容はGCの種別によって異なります。今回は一番わかりやすいシリアルGCとパラレルGCを使用して説明します。CMS GCやG1 GCに関しては、別記事にて解説を予定しています。

本記事は、デジタルトランスフォーメーションを支えるアプリケーションサーバー「FUJITSU Software Enterprise Application Platform」のOpenJDK 11を例に説明します。

2. JVM統合ロギングフレームワーク

JDK 8までは、JVMの機能ごとにログの採取方法やフォーマットが異なっていましたが、ログを使用する機能が増え続けるなかで、統一したロギングフレームワークが必要となってきました。
そこで、OpenJDKコミュニティーの中で、「JEP 158: Unified JVM Logging」および、「JEP 271: Unified GC Logging」が提案されました。JEP 158では、コマンドラインオプションの共通化、フォーマットの統一、ログレベルの導入、動的変更の仕組み、などが、ロギングフレームワークに組み込まれました。

JVM統合ロギングフレームワークを使用するには、-Xlogオプションを指定します。-Xlogオプションの詳細については、「JVM統合ロギングフレームワークを使用したロギングの有効化（「Oracle Help Center」のページへ）」を参照してください。

-Xlog[:[what][:[output][:[decorators][:output-options[,…]]]

3. GCログの採取方法

「JVM統合ロギングフレームワーク」でGCログを採取する場合は、-Xlogオプションを指定する必要があります。この章では「JVM統合ロギングフレームワーク」によるGCログの採取方法について解説します。

3.1. Javaのガーベジコレクション（GC）ログの出力オプション

-XlogオプションでGCログを採取する場合、以下のように、「what」の部分に「gc」を設定します。また、「output」には出力先を、「decorators」には出力フォーマットをそれぞれ設定できます。

-Xlog:gc[*][:[output][:[decorators]]]

オプションの例を以下の表で示します。目的に合わせて指定してください。

3.2. 非推奨オプション

以下の表に記載したオプションは、JDK 8では利用できましたが、JDK 11では非推奨となります。-Xlog:gcを利用してください。

4. Javaのガーベジコレクション（GC）ログの読み方（シリアルGC / パラレルGC）

この章では、シリアルGCとパラレルGCにおいてGCログの共通となる読み方について紹介します。

シリアルGCは単一スレッドで動作する軽量なGCです。CPUのコア数が少ない場合、または使用するヒープ量が小さい場合の動作に適しているため、主にデスクトップクライアント環境で動作するアプリケーションに適しています。シリアルGCを使用するには、-XX:+UseSerialGCオプションを指定します。

パラレルGCはGC処理を複数のスレッドで動作させることでGC実行時間を短縮するもので、主にスループット性能を重視するアプリケーションに適しています。パラレルGCを使用するには、-XX:+UseParallelGCオプションを指定します。パラレルGC使用時、デフォルトではFull GCも複数スレッドで並列実行されます（パラレルオールドGC）。
ただし、-XX:-UsePrallelOldGCオプションを指定することで、Full GC処理を単一スレッドで実施させることもできます。

4.1. 簡易ログ（-Xlog:gc）

シリアルGCとパラレルGCでは、GC対象となる領域が世代別に分かれて管理されています。New世代領域を対象にしたGCを「New GC」、New世代領域・Old世代領域などを対象にしたGCを「Full GC」と呼びます。なお、世代別領域については「世代別ガベージ・コレクション（「Oracle Help Center」のページへ）」を参照してください。

-Xlog:gcを指定した時の出力形式（簡易ログ）について、New GCとFull GCのそれぞれについて説明します。

4.1.1. New GC

出力形式

[タイムスタンプ][info][gc] GC(GC通し番号) Pause Young (GC発生理由) GC直前のヒープ使用サイズ->GC直後のヒープ使用サイズ(ヒープサイズ) GC時間

出力例

[15.010s][info][gc] GC(28) Pause Young (Allocation Failure) 340M->292M(455M) 22.227ms

意味

出力例のログからは以下の内容が読み取れます。

• JMV起動から15.01秒後にNew世代領域不足が原因で、28回目のGCが発生しています。
• ヒープ使用量は340MBから292MBになり、GC後のヒープサイズは455MBです。
• このGC処理に費やした時間は、22.227msです。

4.1.2. Full GC

出力形式

[タイムスタンプ][info][gc] GC(GC通し番号) Pause Full (GC発生理由) GC直前のヒープ使用サイズ->GC直後のヒープ使用サイズ(ヒープサイズ) GC時間

出力例

[15.561s][info][gc] GC(29) Pause Full (Ergonomics) 292M->284M(455M) 550.828ms

意味

出力例のログからは以下の内容が読み取れます。

• JVM起動から15.561秒後に領域不足（注1）が原因で、29回目のGCが発生しています。
• ヒープ使用量は292MBから284MBになり、GC後のヒープサイズは455MBです。
• このGC処理に費やした時間は、550.828msです。

• 注1
  Ergonomicsと表示された場合、New世代領域が不足し実施したNew GCで失敗、あるいは、Old世代領域の空きが不足して今後のNew GCに失敗すると判断されたため、Full GCが発生しています。JVMのエルゴノミクスについては、「付録. エルゴノミクス」を参照してください。

4.2. 詳細ログ（-Xlog:gc*）

-Xlog:gc*を指定した時の出力形式（詳細ログ）について、New GCとFull GCのそれぞれについて説明します。1つのGC処理に対して複数行の出力が行われます。

4.2.1. New GC

出力形式

[タイムスタンプ][info][gc,start       ] GC(GC通し番号) Pause GC (GC発生理由)
[タイムスタンプ][info][gc,heap        ] GC(GC通し番号) 対象の世代領域名: GC直前の使用サイズ->GC直後の使用サイズ(世代領域サイズ)
[タイムスタンプ][info][gc,metaspace   ] GC(GC通し番号) Metaspace: GC直前のmetaspace使用サイズ->GC直後のmetaspace使用サイズ(metaspaceサイズ)
[タイムスタンプ][info][gc             ] GC(GC通し番号) Pause Young (GC発生理由) GC直前のJavaヒープ使用サイズ->GC直後のJavaヒープ使用サイズ(ヒープサイズ) GC時間
[タイムスタンプ][info][gc,cpu         ] GC(GC通し番号) User=UUUs Sys=SSSs Real=RRRs

• 注2
  UUU、SSS、RRRは、GC処理で使用した時間を示す数値（秒）で、それぞれ、ユーザーCPU時間、システムCPU時間、経過時間を示します。

以下は、シリアルGCとパラレルGCの出力例ですが、世代領域名が異なる以外は、同じ内容になります。

出力例（シリアルGC）

[12.088s][info][gc,start       ] GC(18) Pause Young (Allocation Failure)
[12.144s][info][gc,heap        ] GC(18) DefNew: 157248K->17471K(157248K)
[12.144s][info][gc,heap        ] GC(18) Tenured: 280045K->285408K(349568K)
[12.144s][info][gc,metaspace   ] GC(18) Metaspace: 13272K->13272K(1060864K)
[12.144s][info][gc             ] GC(18) Pause Young (Allocation Failure) 427M->295M(494M) 56.154ms
[12.144s][info][gc,cpu         ] GC(18) User=0.09s Sys=0.00s Real=0.06s

意味

出力例のログからは以下の内容が読み取れます。

• New世代領域不足が原因で、18回目のGCが発生しました。
  • New世代領域（DefNew）の使用量は、157,248KBから17,471KBになり、GC後の領域サイズは157,248KBです。
  • Old世代領域（Tenured）の使用量は、280,045KBから285,408KBになり、GC後の領域サイズは349,568KBです。
  • Metaspace領域の使用量は13,272KBのままで、GC後の領域サイズは1,060,864KBです。
• ヒープ全体では、使用量が427MBから295MBになり、処理時間が56.154msでした。

出力例（パラレルGC）

[7.646s][info][gc,start       ] GC(16) Pause Young (Allocation Failure)
[7.682s][info][gc,heap        ] GC(16) PSYoungGen: 68032K->9280K(116736K)
[7.683s][info][gc,heap        ] GC(16) ParOldGen: 280578K->287666K(349696K)
[7.683s][info][gc,metaspace   ] GC(16) Metaspace: 13304K->13304K(1060864K)
[7.683s][info][gc             ] GC(16) Pause Young (Allocation Failure) 340M->289M(455M) 36.578ms
[7.683s][info][gc,cpu         ] GC(16) User=0.07s Sys=0.01s Real=0.04s

意味

出力例のログからは以下の内容が読み取れます。

• New世代領域不足が原因で、16回目のGCが発生しました。
  • New世代領域（PSYoungGen）の使用量は、68,032KBから9,280KBになり、GC後の領域サイズは116,736KBです。
  • Old世代領域（ParOldGen）の使用量は、280,578KBから287,666KBになり、GC後の領域のサイズは349,696KBです。
  • Metaspace領域の使用量は13,304KBのままで、GC後の領域サイズは1,060,864KBです。
• ヒープ全体では、使用量が340MBから289MBになり、処理時間が36.578msでした。

4.2.2. Full GC

出力形式

[タイムスタンプ][info][gc,start       ] GC(GC通し番号) Pause Full (GC発生理由)
[タイムスタンプ][info][gc,phases,start] GC(GC通し番号) Phase GCフェーズの通し番号: GCフェーズの処理名
[タイムスタンプ][info][gc,phases      ] GC(GC通し番号) Phase GCフェーズの通し番号: GCフェーズの処理名 GCフェーズの処理時間
[タイムスタンプ][info][gc,heap        ] GC(GC通し番号) 対象の世代領域名: GC直前の使用サイズ->GC直後の使用サイズ(世代領域サイズ)
[タイムスタンプ][info][gc,metaspace   ] GC(GC通し番号) Metaspace: GC直前のmetaspace使用サイズ->GC直後のmetaspace使用サイズ(metaspaceサイズ)
[タイムスタンプ][info][gc             ] GC(GC通し番号) Pause Full (GC発生理由) GC直前のJavaヒープ使用サイズ->GC直後のJavaヒープ使用サイズ GC時間(ヒープサイズ)
[タイムスタンプ][info][gc,cpu         ] GC(GC通し番号) User=UUUs Sys=SSSs Real=RRRs

• 注3
  UUU、SSS、RRRは、GC処理で使用した時間を示す数値（秒）で、それぞれ、ユーザーCPU時間、システムCPU時間、経過時間を示します。
• 注4
  シリアルGCでは、CPU時間情報は、GC発生理由がSystem.gc()の場合に出力されます。

以下は、シリアルGCとパラレルGCの出力例ですが、世代領域名およびGCフェーズが異なります。

出力例（シリアルGC）

[12.533s][info][gc,start       ] GC(20) Pause Full (Allocation Failure)
[12.533s][info][gc,phases,start] GC(20) Phase 1: Mark live objects
[12.741s][info][gc,phases      ] GC(20) Phase 1: Mark live objects 207.725ms
[12.741s][info][gc,phases,start] GC(20) Phase 2: Compute new object addresses
[12.895s][info][gc,phases      ] GC(20) Phase 2: Compute new object addresses 154.720ms
[12.895s][info][gc,phases,start] GC(20) Phase 3: Adjust pointers
[13.033s][info][gc,phases      ] GC(20) Phase 3: Adjust pointers 137.146ms
[13.033s][info][gc,phases,start] GC(20) Phase 4: Move objects
[13.050s][info][gc,phases      ] GC(20) Phase 4: Move objects 17.793ms
[13.051s][info][gc             ] GC(20) Pause Full (Allocation Failure) 432M->241M(494M) 518.108ms

意味

出力例のログからは以下の内容が読み取れます。

• 領域不足が原因で、20回目のGCが発生しました。
• フェーズごとの処理時間は以下のとおりです。
  • Mark live objects：207.725ms
  • Compute new object addresses：154.72ms
  • Adjust pointers：173.146ms
  • Move objects：17.793ms
• ヒープ全体では、使用量が432MBから241MBになり、処理時間が518.108msでした。

出力例（パラレルGC）

[7.683s][info][gc,start       ] GC(17) Pause Full (Ergonomics)
[7.683s][info][gc,phases,start] GC(17) Marking Phase
[8.025s][info][gc,phases      ] GC(17) Marking Phase 341.989ms
[8.025s][info][gc,phases,start] GC(17) Summary Phase
[8.025s][info][gc,phases      ] GC(17) Summary Phase 0.017ms
[8.025s][info][gc,phases,start] GC(17) Adjust Roots
[8.036s][info][gc,phases      ] GC(17) Adjust Roots 11.168ms
[8.036s][info][gc,phases,start] GC(17) Compaction Phase
[8.546s][info][gc,phases      ] GC(17) Compaction Phase 509.993ms
[8.546s][info][gc,phases,start] GC(17) Post Compact
[8.548s][info][gc,phases      ] GC(17) Post Compact 1.806ms
[8.548s][info][gc,heap        ] GC(17) PSYoungGen: 9280K->0K(116736K)
[8.548s][info][gc,heap        ] GC(17) ParOldGen: 287666K->229676K(349696K)
[8.548s][info][gc,metaspace   ] GC(17) Metaspace: 13304K->13304K(1060864K)
[8.548s][info][gc             ] GC(17) Pause Full (Ergonomics) 289M->224M(455M) 865.247ms
[8.548s][info][gc,cpu         ] GC(17) User=1.67s Sys=0.02s Real=0.86s

意味

出力例のログからは以下の内容が読み取れます。

• 領域不足（注5）が原因で、17回目のGCが発生しました。
• フェーズごとの処理時間は以下のとおりです。
  • Marking Phase：341.989ms
  • Summary Phase：0.017ms
  • Adjust Roots：11.168ms
  • Compaction Phase：509.993ms
  • Post Compact：1.806ms
• New世代領域（PSYoungGen）の使用量は、9,280KBから0KBになり、GC後の領域サイズは116,736KBです。
• Old世代領域（ParOldGen）の使用量は、287,666KBから229,676KBになり、GC後の領域サイズは349,696KBです。
• Metaspace領域の使用量は、13,304KBのままで、GC後の領域サイズは1,062,912KBです。
• ヒープ全体では、使用量が289MBから224MBになり、処理時間が865.247msでした。

• 注5
  記載されている「Ergonomics」については、「付録. エルゴノミクス」を参照してください。

出力例（パラレルGC、パラレルオールドGCを無効にした場合）

[7.220s][info][gc,start       ] GC(17) Pause Full (Ergonomics)
[7.220s][info][gc,phases,start] GC(17) Phase 1: Mark live objects
[7.454s][info][gc,phases      ] GC(17) Phase 1: Mark live objects 233.053ms
[7.454s][info][gc,phases,start] GC(17) Phase 2: Compute new object addresses
[7.557s][info][gc,phases      ] GC(17) Phase 2: Compute new object addresses 103.607ms
[7.557s][info][gc,phases,start] GC(17) Phase 3: Adjust pointers
[7.702s][info][gc,phases      ] GC(17) Phase 3: Adjust pointers 145.089ms
[7.702s][info][gc,phases,start] GC(17) Phase 4: Move objects
[7.726s][info][gc,phases      ] GC(17) Phase 4: Move objects 23.405ms
[7.726s][info][gc,heap        ] GC(17) PSYoungGen: 9248K->0K(116736K)
[7.726s][info][gc,heap        ] GC(17) PSOldGen: 287351K->247386K(349696K)
[7.726s][info][gc,metaspace   ] GC(17) Metaspace: 13304K->13304K(1062912K)
[7.726s][info][gc             ] GC(17) Pause Full (Ergonomics) 289M->241M(455M) 505.936ms
[7.726s][info][gc,cpu         ] GC(17) User=0.60s Sys=0.00s Real=0.51s

意味

出力例のログからは以下の内容が読み取れます。

• 領域不足（注6）が原因で、17回目のGCが発生しました。
• フェーズごとの処理時間は以下のとおりです。
  • Mark live objects：233.053ms
  • Compute new object addresses：103.607ms
  • Adjust pointers：145.089ms
  • Move objects：23.405ms
• New領域（PSYoungGen）の使用量は、9,248KBから0KBになり、GC後の領域サイズは116,736KBです。
• Old領域（PSOldGen）の使用量は、287,351KBから247,386KBになり、GC後の領域サイズは349,696KBです。
• Metaspace領域の使用量は、13,304KBのままで、GC後の領域サイズは1,060,864KBです。
• ヒープ全体では、使用量が289MBから241MBになり、処理時間が505.936msでした。

• 注6
  記載されている「Ergonomics」については、「付録. エルゴノミクス」を参照してください。

5. Javaのガーベジコレクション（GC）ログの分析

この章では、GCログを分析するポイントについて解説します。

（1）長時間GC発生の確認

GC処理時間が長いGCがあるかどうかを確認します（以降の説明では、処理時間が長いGCのことを「長時間GC」と表現します）。以下は、パラレルGCのFull GCで、長時間GCが発生している例です。
GCログにPauseと出力されている場合、GC処理によりアプリケーションが停止することを示しています。以下の例では赤字で書かれているGCがそれぞれ9秒（9043.206ms）、11秒（11992.944ms）の時間を費やしていることが読み取れます。

簡易ログ：
[20.294s][info][gc] GC(9) Pause Full (Ergonomics) 1092M->1063M(1678M) 9043.206ms

詳細ログ：
[55.586s][info][gc,start       ] GC(13) Pause Full (Ergonomics)
[55.586s][info][gc,phases,start] GC(13) Marking Phase
[62.247s][info][gc,phases      ] GC(13) Marking Phase 6660.840ms
[62.247s][info][gc,phases,start] GC(13) Summary Phase
[62.247s][info][gc,phases      ] GC(13) Summary Phase 0.068ms
[62.247s][info][gc,phases,start] GC(13) Adjust Roots
[62.264s][info][gc,phases      ] GC(13) Adjust Roots 17.037ms
[62.264s][info][gc,phases,start] GC(13) Compaction Phase
[66.001s][info][gc,phases      ] GC(13) Compaction Phase 3655.816ms
[66.133s][info][gc,phases,start] GC(13) Post Compact
[67.073s][info][gc,phases      ] GC(13) Post Compact 699.210ms
[67.362s][info][gc,heap        ] GC(13) PSYoungGen: 37216K->0K(465920K)
[67.407s][info][gc,heap        ] GC(13) ParOldGen: 1101894K->1107755K(1398272K)
[67.491s][info][gc,metaspace   ] GC(13) Metaspace: 13502K->13502K(1062912K)
[67.607s][info][gc             ] GC(13) Pause Full (Ergonomics) 1112M->1081M(1820M) 11992.944ms
[67.624s][info][gc,cpu         ] GC(13) User=6.00s Sys=0.07s Real=12.04s

GC処理に許容される時間はアプリケーションに依存しますが、1秒以上費やすGCはアプリケーションの性能に影響している可能性があります。

アプリケーションに、レスポンス遅延が発生している場合は、長時間GCの発生時刻とレスポンス遅延発生時刻を照らし合わせます。それらが一致する場合、GCによってアプリケーションが長時間停止し、性能問題を引き起こしていると考えられます。このような場合は、長時間GCの発生を防ぐように、Javaヒープサイズ等のチューニングが必要です。

（2）Full GC後のヒープ使用量の確認

Full GC後のヒープ使用量が増え続けている場合、メモリーリークが発生している可能性があります。複数回Full GCが発生しているGCログから「GC直後のJavaヒープ使用サイズ」をプロットしたグラフを作成すると、ヒープ使用量が増加傾向にあるかどうかが分かります。

以下は簡易ログにおけるFull GCの出力例ですが、プロットする値となる「GC直後のJavaヒープ使用サイズ」は赤字で書かれている値です。

[151.804s][info][gc] GC(390) Pause Full (Ergonomics) 484M->290M(489M) 626.136ms
[163.442s][info][gc] GC(425) Pause Full (Ergonomics) 352M->313M(458M) 649.544ms
[184.115s][info][gc] GC(501) Pause Full (Ergonomics) 468M->341M(472M) 886.016ms
[185.650s][info][gc] GC(502) Pause Full (Ergonomics) 434M->353M(472M) 1234.186ms

図1は、生存オブジェクトの量をプロットしてグラフを作成した例です。

図1 生存オブジェクト量が増加傾向にある例

このような傾向がみられる場合は、ヒープダンプやヒープヒストグラムを採取し、メモリーリークが発生しているかを特定します。ヒープダンプやヒープヒストグラムの採取方法やメモリーリークの特定方法は、別記事で解説を予定しています。

6. おわりに

今回は、GCログの読み方を紹介して、GCに関わるトラブルの確認方法について説明しました。GCの頻発や長時間GC、メモリーリークは、アプリケーションの停止やレスポンス悪化のトラブルにつながりますので、本記事を安定稼働の参考にしてください。
次回は、CMS GC、G1 GCのログの読み方を紹介します。

付録. エルゴノミクス

エルゴノミクスとは、JVMがパフォーマンスを向上させるために、GCの種別やヒープサイズを自動的に最適化する機能のことです。
エルゴノミクスでは-XX:+UseParallelGCなどのオプションで明示的に指定しない限り、GCの種別はG1 GCが使用されます。-Xmxや-Xmsなどのオプションで明示的に指定しない限り、使用可能なCPUや物理メモリーから計算されたヒープサイズの最大値と最小値が自動的に設定されます。
エルゴノミクスは、内部でこの最大値と最小値の範囲でヒープサイズを自動で調整し、GCによるアプリケーション最大一時停止時間とスループット性能の目標を達成するように最適化します。
Full GCのGCログの出力例ではGCの発生理由として「Ergonomics」と表記されています。この表記の理由は、Full GCの前に実施されたNew世代GCによってOld世代領域に移動したオブェクトサイズの統計情報を採取して、 この次にNew世代GCを実施した場合に自動設定されたOld世代領域のサイズでは不足する可能性があると、JVMが自動的に判断した結果、Full GCが発生したためです。