1. ホーム
  2. 製品
  3. ソフトウェア
  4. 富士通のソフトウェアとは
  5. 特集
  6. 富士通Javaブログ
  7. Javaの性能トラブルを防止 ～Javaのガーベジコレクション（GC）ログの見方を知る（CMS GC編）～

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

2022年12月9日 初版
倉繁 泰三

【目次】

1. はじめに

JavaアプリケーションはJava仮想マシン（Java Virtual Machine：以降、「JVM」と表記します）により実行される際、不要になったJavaオブジェクトの解放は、JVMが提供するガーベジコレクターによって自動的に行われます。ガーベジコレクターによるメモリー解放処理であるガーベジコレクション（以降、「GC」と表記します）により、ユーザーはメモリー解放を意識する必要はなくなります。しかし、一方で、一般的なガーベジコレクターでは、GC処理中はアプリケーションの処理が停止するため、GCの長時間化や頻発は性能トラブルに直結します。

GCに関する性能トラブル調査には、GCログが有用です。GCログには、GC処理に費やした時間やGC前後のメモリー使用状況などが出力されるため、これらを分析することでチューニングやプログラムの修正に役立てることができます。
以前に掲載した『Javaの性能トラブルを防止 ～Javaのガーベジコレクション（GC）ログの見方を知る（シリアルGC / パラレルGC編）～』では、シリアルGC / パラレルGCにおけるログの読み方について説明しました。
今回は、Concurrent Mark-Sweep GC（以降、「CMS GC」と表記します）におけるログの読み方について説明します。

本記事は、FUJITSU Software Enterprise Application PlatformのOpenJDK 11を例に説明します。製品の詳細は下記より製品情報ページをご覧ください。

2. CMS GCの特徴

CMS GCは、GC処理の一部をアプリケーションの実行と並列に処理することで、Full GCの発生をできる限り抑えて、アプリケーションの停止時間を短くするように動作します。

2.1. CMS GCの仕組み

CMS GCは、シリアルGC / パラレルGCと同様に、GC対象となる領域が世代別に管理されています。New世代領域を対象にしたGCを「New GC」、New世代領域・Old世代領域などを対象にしたGCを「Full GC」と呼びます。
CMS GCは、Old領域におけるGC処理の一部をアプリケーションの実行と並列に処理することで、アプリケーションの停止時間を短くすることが可能です。この、アプリケーションの実行と並列に行うGC処理を、「コンカレントGC」と呼びます。コンカレントGCは、複数のフェーズから成ります。ただし、コンカレントGCには、アプリケーションと並列実行できないフェーズもあり、そのようなフェーズはアプリケーションを停止して行われます。
コンカレントGCにおけるオブジェクトの回収が終了せず、Old領域の容量が不足している場合は、Full GCが発生してアプリケーションが停止されます。

New領域のGCはシリアルGC / パラレルGCと同様にアプリケーションを停止して行われます。

2.2. CMS GCの長所と短所

CMS GCは、適切なチューニングを行えば、Full GCの発生を抑え、アプリケーションの停止時間を短くすることが可能です。Javaヒープサイズ、Javaヒープ内の各領域のサイズを決めるオプション、CMS GCの動作を決めるオプション等を使用することで、チューニングを行うことができます。各オプションの詳細説明はオラクル社が提供する「Java Platform, Standard Edition ツール・リファレンス, リリース11」を参照してください。

一方、CMS GCの動作を決めるオプションは多く、どのようなチューニングを行うべきかはアプリケーションの実装に依存します。そのため、どのようなオプションを組み合わせて、どのような値を指定してチューニングを行うべきかを決めることは簡単ではありません。
また、アプリケーションと並列にGC処理を行うため、CPU使用率が増加しやすいです。

3. Javaのガーベジコレクション（GC）ログの読み方（CMS GC）

3.1. 前置き

CMS GCでは、「2.1. CMS GCの仕組み」で説明したように、New GC、Full GC、コンカレントGCの3種類のGC処理が行われます。

-Xlogオプションで採取できるGCログには、-Xlog:gcオプションで得られる簡易的なログ（以降、「簡易ログ」と表記します）と、-Xlog:gc*オプションで得られる詳細なログ（以降、「詳細ログ」と表記します）があります。

簡易ログ、詳細ログでのNew GC、Full GC、コンカレントGCのそれぞれのログの読み方について説明します。

3.2 簡易ログ（-Xlog:gc）

3.2.1 New GC

【出力形式】

太字の部分が可変情報で、それ以外の部分は固定情報です。

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

【出力例】

[0.606s][info][gc] GC(2) Pause Young (Allocation Failure) 69M->7M(247M) 6.772ms

【意味】

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

  • JVM起動から0.606秒後にNew世代領域不足が原因で、2回目のGCが発生しています。
  • ヒープ使用量は69MBから7MBになり、GC後のヒープサイズは247MBです。
  • このGC処理に費やした時間は、6.772msです。

3.2.2 Full GC

【出力形式】

太字の部分が可変情報で、それ以外の部分は固定情報です。

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

【出力例】

[2.022s][info][gc] GC(9) Pause Full (Allocation Failure) 226M->176M(247M) 344.529ms

【意味】

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

  • JVM起動から2.022秒後に領域不足が原因で、9回目のGCが発生しています。
  • ヒープ使用量は226MBから176MBになり、GC後のヒープサイズは247MBです。
  • このGC処理に費やした時間は、344.529msです。

3.2.3 コンカレントGC

コンカレントGCは複数のフェーズから成り、それぞれのフェーズのログが出力されます。
また、コンカレントGCのログは、New GCやFull GCのログの途中に混ざって出力される場合があります。GC通し番号が一致するログを参照してください。

【出力形式】

太字の部分が可変情報で、それ以外の部分は固定情報です。また、Pause Initial MarkフェーズとPause Remarkフェーズは、フェーズ名だけの行が出力されません。フェーズによってサイズが出力されない場合もあります。

[タイムスタンプ][info][gc] GC(GC通し番号) GCフェーズの処理名
[タイムスタンプ][info][gc] GC(GC通し番号) GCフェーズの処理名 GC直前のOld世代領域使用サイズ->GC直後のOld世代領域使用サイズ(ヒープサイズ) GC時間

【出力例】

[1.247s][info][gc] GC(6) Pause Initial Mark 122M->122M(247M) 1.714ms
[1.247s][info][gc] GC(6) Concurrent Mark
[1.326s][info][gc] GC(6) Concurrent Mark 79.083ms
[1.326s][info][gc] GC(6) Concurrent Preclean
[1.327s][info][gc] GC(6) Concurrent Preclean 0.541ms
[1.327s][info][gc] GC(6) Concurrent Abortable Preclean
[1.479s][info][gc] GC(6) Concurrent Abortable Preclean 152.527ms
[1.483s][info][gc] GC(6) Pause Remark 182M->182M(247M) 3.769ms
[1.483s][info][gc] GC(6) Concurrent Sweep
[1.531s][info][gc] GC(6) Concurrent Sweep 48.003ms
[1.531s][info][gc] GC(6) Concurrent Reset
[1.531s][info][gc] GC(6) Concurrent Reset 0.238ms

【意味】

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

  • フェーズごとの処理時間は以下のとおりです。
    • Pause Initial Mark：1.714ms
    • Concurrent Mark：79.083ms
    • Concurrent Preclean：0.541ms
    • Concurrent Abortable Preclean：152.527ms
    • Pause Remark：3.769ms
    • Concurrent Sweep：48.003ms
    • Concurrent Reset：0.238ms
  • Pauseから始まるフェーズは、パラレルGCなどと同様にアプリケーションを停止して処理を行います。Concurrentから始まるフェーズはアプリケーション処理のバックグラウンドで並列に実行されます。それぞれ合計すると、5.483msはアプリケーションを停止し、280.392msはアプリケーションの処理と並列でGC処理が行われたことが分かります。

3.3 詳細ログ（-Xlog:gc*）

3.3.1 New GC

【出力形式】

太字の部分が可変情報で、それ以外の部分は固定情報です。また、UUU、SSS、RRRは、GC処理で使用した時間を示す数値（秒）で、それぞれ、ユーザーCPU時間、システムCPU時間、経過時間を示します。

[タイムスタンプ][info][gc,start       ] GC(GC通し番号) Pause Young (GC発生理由)
[タイムスタンプ][info][gc,task        ] GC(GC通し番号) Using (アクティブな退避スレッド数) workers of (全退避スレッド数) for evacuation
[タイムスタンプ][info][gc,heap        ] GC(GC通し番号) ParNew: GC直前のNew世代領域使用サイズ->GC直後のNew世代領域使用サイズ(New世代領域サイズ)
[タイムスタンプ][info][gc,heap        ] GC(GC通し番号) CMS: GC直前のOld世代領域使用サイズ->GC直後のOld世代領域使用サイズ(Old世代領域使用サイズ)
[タイムスタンプ][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

【出力例】

[0.738s][info][gc,start       ] GC(3) Pause Young (Allocation Failure)
[0.738s][info][gc,task        ] GC(3) Using 4 workers of 4 for evacuation
[0.859s][info][gc,heap        ] GC(3) ParNew: 76606K->8704K(78656K)
[0.859s][info][gc,heap        ] GC(3) CMS: 1270K->40865K(174784K)
[0.859s][info][gc,metaspace   ] GC(3) Metaspace: 12894K->12894K(1060864K)
[0.859s][info][gc             ] GC(3) Pause Young (Allocation Failure) 76M->48M(247M) 121.508ms
[0.859s][info][gc,cpu         ] GC(3) User=0.46s Sys=0.00s Real=0.12s

【意味】

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

  • New世代領域不足が原因で、3回目のGCが発生しました。
    • New世代領域（ParNew）の使用量は、76,606KBから8704KBになり、GC後の領域サイズは78,656KBです。
    • Old世代領域（CMS）の使用量は、1,270KBから40,865KBになり、GC後の領域サイズは174,784KBです。
    • Metaspace領域の使用量は12,894Kのままで、GC後の領域サイズは1,060,864KBです。
    • ヒープ全体では、使用量が76MBから48MBになり、処理時間が121.508msでした。

3.3.2 Full GC

【出力形式】

太字の部分が可変情報で、それ以外の部分は固定情報です。

[タイムスタンプ][info][gc,start       ] GC(GC通し番号) Pause Full (Allocation Failure)
[タイムスタンプ][info][gc,phases,start] GC(GC通し番号) Phase GCフェーズの通し番号: GCフェーズの処理名
[タイムスタンプ][info][gc,phases      ] GC(GC通し番号) Phase GCフェーズの通し番号: GCフェーズの処理名 GCフェーズの処理時間
[タイムスタンプ][info][gc             ] GC(GC通し番号) Pause Full (GC発生理由) GC直前のJavaヒープ使用サイズ->GC直後のJavaヒープ使用サイズ(ヒープサイズ) GC時間

【出力例】

[1.637s][info][gc,start       ] GC(9) Pause Full (Allocation Failure)
[1.637s][info][gc,phases,start] GC(9) Phase 1: Mark live objects
[1.754s][info][gc,phases      ] GC(9) Phase 1: Mark live objects 117.029ms
[1.754s][info][gc,phases,start] GC(9) Phase 2: Compute new object addresses
[1.838s][info][gc,phases      ] GC(9) Phase 2: Compute new object addresses 84.129ms
[1.838s][info][gc,phases,start] GC(9) Phase 3: Adjust pointers
[1.928s][info][gc,phases      ] GC(9) Phase 3: Adjust pointers 89.722ms
[1.928s][info][gc,phases,start] GC(9) Phase 4: Move objects
[1.980s][info][gc,phases      ] GC(9) Phase 4: Move objects 52.299ms
[1.980s][info][gc             ] GC(9) Pause Full (Allocation Failure) 226M->176M(247M) 343.834ms

【意味】

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

  • 領域不足が原因で、9回目のGCが発生しました。
    • フェーズごとの処理時間は以下のとおりです。
      • Mark live objects：117.029ms
      • Compute new object addresses：84.129ms
      • Adjust pointers：89.722ms
      • Move objects：52.299ms
    • ヒープ全体では、使用量が226MBから176MBになり、処理時間が343.834msでした。

3.3.3 コンカレントGC

【出力形式】

太字の部分が可変情報で、それ以外の部分は固定情報です。また、UUU、SSS、RRRは、GC処理で使用した時間を示す数値（秒）で、それぞれ、ユーザーCPU時間、システムCPU時間、経過時間を示します。なお、フェーズによってサイズが出力されない場合もあります。さらに簡易ログの場合は、gc,start、gc,cpu、gc,heapの行が出力されません。

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

【出力例】

[1.221s][info][gc,start       ] GC(6) Pause Initial Mark
[1.222s][info][gc             ] GC(6) Pause Initial Mark 122M->122M(247M) 1.420ms
[1.222s][info][gc,cpu         ] GC(6) User=0.00s Sys=0.00s Real=0.00s
[1.222s][info][gc             ] GC(6) Concurrent Mark
[1.304s][info][gc             ] GC(6) Concurrent Mark 81.922ms
[1.304s][info][gc,cpu         ] GC(6) User=0.17s Sys=0.00s Real=0.09s
[1.304s][info][gc             ] GC(6) Concurrent Preclean
[1.305s][info][gc             ] GC(6) Concurrent Preclean 0.567ms
[1.305s][info][gc,cpu         ] GC(6) User=0.00s Sys=0.00s Real=0.00s
[1.305s][info][gc             ] GC(6) Concurrent Abortable Preclean
[1.448s][info][gc             ] GC(6) Concurrent Abortable Preclean 143.151ms
[1.448s][info][gc,cpu         ] GC(6) User=0.37s Sys=0.00s Real=0.14s
[1.448s][info][gc,start       ] GC(6) Pause Remark
[1.452s][info][gc             ] GC(6) Pause Remark 183M->183M(247M) 3.849ms
[1.452s][info][gc,cpu         ] GC(6) User=0.01s Sys=0.00s Real=0.00s
[1.452s][info][gc             ] GC(6) Concurrent Sweep
[1.501s][info][gc             ] GC(6) Concurrent Sweep 49.232ms
[1.501s][info][gc,cpu         ] GC(6) User=0.12s Sys=0.00s Real=0.05s
[1.501s][info][gc             ] GC(6) Concurrent Reset
[1.501s][info][gc             ] GC(6) Concurrent Reset 0.248ms
[1.501s][info][gc,cpu         ] GC(6) User=0.00s Sys=0.00s Real=0.00s
[1.502s][info][gc,heap        ] GC(6) Old: 115317K->152780K(174784K)

【意味】

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

  • JVM起動から1.221秒後に、CMS GCの処理が開始されました。
  • フェーズごとの処理時間は以下のとおりです。
    • Pause Initial Mark：1.420ms
    • Concurrent Mark：81.922ms
    • Concurrent Preclean：0.567ms
    • Concurrent Abortable Preclean：143.151ms
    • Pause Remark：3.849ms
    • Concurrent Sweep：49.232ms
    • Concurrent Reset：0.248ms
  • 5.269msはアプリケーションを停止し、275.12msはアプリケーションの処理と並列でGC処理が行われました。
  • Old世代領域の使用量は、115,317KBから152,780KBになり、GC後の領域サイズは174,784KBです。

4. おわりに

今回は、CMS GCログの読み方を紹介しました。CMS GCログを読むことで、Old領域のGC処理の一部がアプリケーションの実行と並列に処理されていることを確認してください。また、本記事を、CMS GCを用いたアプリケーションの安定稼働に向けて参考にしてください。
次回は、G1 GCのログの読み方を紹介します。

こちらもおすすめ

Javaのガーベジコレクション（GC）ログの見方を知る

本コンテンツに関するお問い合わせ

お電話でのお問い合わせ

富士通コンタクトライン（総合窓口）

0120-933-200

受付時間：9時～12時および13時～17時30分
（土曜日・日曜日・祝日・当社指定の休業日を除く）

Webでのお問い合わせ

入力フォーム 

当社はセキュリティ保護の観点からSSL技術を使用しております。

ページの先頭へ