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

2023年6月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におけるログの読み方、『Javaの性能トラブルを防止 ~Javaのガーベジコレクション(GC)ログの見方を知る(CMS GC編)~』ではCMS GCにおけるログの読み方について説明しました。
今回は、Garbage-First GC(以降、「G1 GC」と表記します)におけるログの読み方について説明します。

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

2. Javaのガーベジコレクション(GC)ログの読み方(G1 GC)

2.1 G1 GCとGCログの概要

G1 GCは、Javaヒープを領域(Region)として分割し使用します。各領域は、以下のどれか4つの領域種別に分類されます。

  • Eden領域
  • Survivor領域
  • Old領域
  • Humongous領域

各領域の種別は固定ではなく、Javaプロセス生存中に、別の種別に変更されることがあります。

G1 GCは、以下から構成されています

  • Young GC
  • Concurrent Cycle
  • Mixed GC
  • Full GC

Young GCはEden領域・Survivor領域のGCを、Concurrent CycleはEden領域・Survivor領域・Humongous領域のGCを、Mixed GCはEden領域・Survivor領域・Old領域のGCを、Full GCはすべての領域のGCを行います。なお、例外として、Humongous領域に割り当たっている大型のプリミティブタイプの配列についてはYoung GC・Mixed GCでGCの対象となります。また、Concurrent Cycleでは空になった領域の回収も実施します。
また、Full GC以外のGCで発生するアプリケーションの停止時間は、停止目標時間に収まるように調整されます。停止目標時間のデフォルト値は200msですが、オプション-XX:MaxGCPauseMillisを使用してチューニング可能です。
G1 GCの詳細は、『ガベージファースト・ガベージ・コレクタ(「Oracle Help Center」のページへ)』をご参照ください。

GCで行われる処理に費やした時間や、GC前後でのヒープ使用量などは、「-Xlog」java起動オプションを指定した際に出力されるGCログの内容を参照することで分かります。
-Xlogオプションの詳細は『JVM統合ロギングフレームワークを使用したロギングの有効化(「Oracle Help Center」のページへ)』をご参照ください。
-Xlogオプションで採取できるGCログには、-Xlog:gcオプションによる簡易的なログ(以降、「簡易ログ」と表記します)と、-Xlog:gc*オプションによる詳細なログ(以降、「詳細ログ」と表記します)の2種類があります。それぞれ、2.2、2.3で、各ログのフォーマットと出力例を説明します。

2.2 簡易ログ(-Xlog:gc)

本節では、G1 GCで出力される簡易ログの形式を説明します。

2.2.1 Young GC / Mixed GC

【出力形式】

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

[タイムスタンプ][info][gc] GC(GC通し番号) To-space exhausted
[タイムスタンプ][info][gc] GC(GC通し番号) Pause Young (ラベル) (GC発生理由) GC直前のJavaヒープ使用サイズ->GC直後のJavaヒープ使用サイズ(Javaヒープサイズ) GC時間
  • 「To-space exhausted」のログはGCの際にオブジェクトのコピー先の領域が確保できなかった場合のみ表示されます。通常Full GCの前にはこのログが表示されます。
  • ラベルには以下の4種類があり、これらは実行されるGCの分類を表します。
    • Normal
    • Concurrent Start
    • Prepare Mixed
    • Mixed
    Normalは通常のYoung GC、Concurrent StartはConcurrent Cycleの直前に行われるYoung GC、Prepare MixedはMixed GCの直前に行われるYoung GC、MixedはMixed GCを表します。

【出力例】

[2.242s][info][gc] GC(3) Pause Young (Normal) (G1 Evacuation Pause) 212M->145M(2048M) 79.350ms

【意味】

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

  • JVM起動から2.242秒後に、3回目のGCとして、通常のYoung GCが発生しています。
  • Javaヒープ使用量は212MBから145MBになり、GC後のJavaヒープサイズは2048MBです。
  • このGCに費やした時間は、79.350msです。

2.2.2 Concurrent Cycle

Concurrent Cycleでログとして出力されるフェーズは2種類存在します。アプリケーションを停止して処理を行うGCフェーズとアプリケーションを停止せずに処理を行うMarkingフェーズです。GCフェーズは簡易ログと詳細ログの両方に出力され、Markingフェーズは詳細ログにのみ出力されます。

【出力形式】

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

[タイムスタンプ][info][gc] GC(GC通し番号) Concurrent Cycle
[タイムスタンプ][info][gc] GC(GC通し番号) Pause GCフェーズ名 GC直前のJavaヒープ使用サイズ->GC直後のJavaヒープ使用サイズ(Javaヒープサイズ) GC時間  
[タイムスタンプ][info][gc] GC(GC通し番号) Concurrent Cycle GC時間 
  • Concurrent Cycleは時間を要するフェーズがあるため、同じGC通し番号のログが離れて出力されている場合があります。
  • ログに表れるGCフェーズ名は、Remark、Cleanupの2種類です。
  • Concurrent Cycleは中断される場合があります。GCフェーズのログは、Pause Remarkフェーズが中断された場合は出力されません。Pause Cleanupフェーズが中断された場合は、Pause Remarkフェーズのログだけが出力され、Pause Cleanupフェーズのログは出力されません。

【出力例】

[5.303s][info][gc] GC(25) Concurrent Cycle
[5.963s][info][gc] GC(25) Pause Remark 1310M->1202M(2048M) 8.205ms
[6.383s][info][gc] GC(25) Pause Cleanup 1202M->1202M(2048M) 0.809ms
[6.387s][info][gc] GC(25) Concurrent Cycle 1083.885ms

【意味】

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

  • JVM起動から5.303秒後にConcurrent Cycleが開始されました。
  • Pauseから始まるGCフェーズは、アプリケーションを停止して処理を行います。GCフェーズごとの処理時間は以下のとおりです。
    • Pause Remark:8.205ms
    • Pause Cleanup:0.809ms
  • Concurrent Cycle の期間は、1083.885msでした。

2.2.3 Full GC

【出力形式】

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

【出力例】

[229.661s][info][gc] GC(240) Pause Full (G1 Evacuation Pause) 2047M->1105M(2048M) 539.193ms

【意味】

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

  • JVM起動から229.661秒後にJavaヒープ領域不足が原因で、240回目のGCとして、Full GCが発生しています。
  • Javaヒープ使用量は2047MBから1105MBになり、GC後のJavaヒープサイズは2048MBです。
  • このGCに費やした時間は、539.193msです。

2.3 詳細ログ(-Xlog:gc*)

本節では、G1 GCで出力される詳細ログの形式を説明します。

2.3.1 Young GC / Mixed GC

【出力形式】

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

[タイムスタンプ][info][gc,start       ] GC(GC通し番号) Pause Young (ラベル) (GC発生理由)  
[タイムスタンプ][info][gc,task        ] GC(GC通し番号) Using GCスレッド数 workers of 最大GCスレッド数 for evacuation  
[タイムスタンプ][info][gc             ] GC(GC通し番号) To-space exhausted
[タイムスタンプ][info][gc,phases      ] GC(GC通し番号)   GCフェーズ名GC時間  
[タイムスタンプ][info][gc,heap        ] GC(GC通し番号領域名GC直前の使用領域数->GC直後の使用領域数(GC直後の領域数)  
[タイムスタンプ][info][gc,metaspace   ] GC(GC通し番号) Metaspace: GC直前のMetaspace使用サイズ(GC直前のMetaspaceサイズ)->GC直後のMetaspace使用サイズ(GC直後のMetaspaceサイズ) NonClass: GC直前の使用サイズ(クラス以外の情報を格納するMetaspaceサイズ)->GC直後の使用サイズ(クラス以外の情報を格納するMetaspaceサイズ) Class: GC直前の使用サイズ(クラスの情報を格納するMetaspaceサイズ)->GC直後の使用サイズ(クラスの情報を格納するMetaspaceサイズ)  
[タイムスタンプ][info][gc             ] GC(GC通し番号) Pause Young (ラベル) (GC発生理由GC直前のJavaヒープ使用サイズ->GC直後のJavaヒープ使用サイズ(JavaヒープサイズGC時間  
[タイムスタンプ][info][gc,cpu         ] GC(GC通し番号) User=UUUs Sys=SSSs Real=RRRs
  • 「To-space exhausted」のログはGCの際にオブジェクトのコピー先の領域が確保できなかった場合のみ表示されます。通常Full GCの前にはこのログが表示されます。
  • ログに表れるGCフェーズは、Pre Evacuate Collection Set、Evacuate Collection Set、Post Evacuate Collection Set、Otherの4種類です。
  • GC直後の領域数は、Old領域とHumongous領域に対しては表示されません。
  • Metaspaceの情報では、(GC直後のMetaspaceサイズ)の部分までしか出力されず、領域の内訳情報が出力されない場合があります。
  • UUU、SSS、RRRは、GCで使用した時間を示す数値(秒)で、それぞれ、ユーザーCPU時間、システムCPU時間、経過時間を示します。

【出力例】

[784.757s][info][gc,start       ] GC(2830) Pause Young (Mixed) (G1 Evacuation Pause)
[784.757s][info][gc,task        ] GC(2830) Using 4 workers of 4 for evacuation
[784.788s][info][gc,phases      ] GC(2830)   Pre Evacuate Collection Set: 0.3ms
[784.788s][info][gc,phases      ] GC(2830)   Evacuate Collection Set: 29.6ms
[784.788s][info][gc,phases      ] GC(2830)   Post Evacuate Collection Set: 0.6ms
[784.788s][info][gc,phases      ] GC(2830)   Other: 0.7ms
[784.788s][info][gc,heap        ] GC(2830) Eden regions: 84->0(130)
[784.788s][info][gc,heap        ] GC(2830) Survivor regions: 18->13(13)
[784.788s][info][gc,heap        ] GC(2830) Old regions: 1281->1254
[784.788s][info][gc,heap        ] GC(2830) Humongous regions: 365->365
[784.788s][info][gc,metaspace   ] GC(2830) Metaspace: 26881K(28288K)->26881K(28288K) NonClass: 24103K(25088K)->24103K(25088K) Class: 2778K(3200K)->2778K(3200K)
[784.788s][info][gc             ] GC(2830) Pause Young (Mixed) (G1 Evacuation Pause) 1745M->1630M(2048M) 31.125ms
[784.788s][info][gc,cpu         ] GC(2830) User=0.12s Sys=0.00s Real=0.03s

【意味】

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

  • 2830回目のGCが発生しました。このGCはMixed GCです。
  • Mixed GCに利用可能な4つのGCスレッドのうち、4つのGCスレッドを使用しました。
  • GCフェーズことの処理時間は以下のとおりです。
    • Pre Evacuate Collection Set: 0.3ms
    • Evacuate Collection Set: 29.6ms
    • Post Evacuate Collection Set: 0.6ms
    • Other: 0.7ms
  • 各領域の個数は以下のとおりです。
    • Eden領域: GC前の使用数=84、GC後の使用数=0、GC後に使用可能な数=130
    • Survivor領域: GC前の使用数=18、GC後の使用数=13、GC後に使用可能な数=13
    • Old領域: GC前の使用数=1281、GC後の使用数=1254
    • Humongous領域: GC前の使用数=365、GC後の使用数=365
  • Metaspace領域の使用サイズは、26881KBから26881KBになり、GC後のMetaspaceサイズは28288KBです。
  • Javaヒープ全体では、使用量が1745MBから1630MBになり、処理時間は31.125msでした。
  • GCに要したユーザーCPU時間は0.12s、システムCPU時間は0.00sであり、実際の経過時間は0.03sでした

2.3.2 Concurrent Cycle

【出力形式】

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


[タイムスタンプ][info][gc             ] GC(GC通し番号) Concurrent Cycle  
[タイムスタンプ][info][gc,marking     ] GC(GC通し番号) Concurrent Markingフェーズ名  
[タイムスタンプ][info][gc,marking     ] GC(GC通し番号) Concurrent Markingフェーズ名 Marking時間  
[タイムスタンプ][info][gc,marking     ] GC(GC通し番号) Concurrent Mark (タイムスタンプ)   
[タイムスタンプ][info][gc,marking     ] GC(GC通し番号) Concurrent Mark (Concurrent Mark開始時のタイムスタンプ, タイムスタンプ) Concurrent Mark時間  
[タイムスタンプ][info][gc,task        ] GC(GC通し番号) Using GCスレッド数 workers of 最大GCスレッド数 for marking  
[タイムスタンプ][info][gc,stringtable ] GC(GC通し番号) Cleaned string and symbol table, strings: stringtableのエントリ数 processed, 削除したstringtableのエントリ数 removed, symbols: symbol tableのエントリ数 processed, 削除したsymbol tableのエントリ数 removed  
[タイムスタンプ][info][gc,start       ] GC(GC通し番号) Pause GCフェーズ名  
[タイムスタンプ][info][gc             ] GC(GC通し番号) Pause GCフェーズ名 GC直前のJavaヒープ使用サイズ->GC直後のJavaヒープ使用サイズ(Javaヒープサイズ) GC時間  
[タイムスタンプ][info][gc,cpu         ] GC(GC通し番号) User=UUUs Sys=SSSs Real=RRRs  
[タイムスタンプ][info][gc             ] GC(GC通し番号) Concurrent Cycle 処理時間  
  • Concurrent Cycleは時間を要するフェーズがあるため、同じGC通し番号のログが離れて出力されている場合があります。
  • Concurrent Cycleは、Full GCの発生など、何らかの理由で中断される場合があります。その場合は一部のみログとして出力されます。
  • ログに表れるMarkingフェーズはClear Claimed Marks、Scan Root Regions、Mark From Roots、Preclean、Rebuild Remembered Sets、Cleanup for Next Markの6種類です。
  • Concurrent MarkはConcurrent Mark From RootsフェーズとConcurrent Precleanフェーズとその関連処理から構成されるフェーズです。
  • stringtableは、クラス名やメソッド名などをJVM内で管理するためのテーブルに関する情報であり、Pause Remarkで出力されます。
  • ログに表れるGCフェーズはRemark、Cleanupの2種類です。GC時間は、GCフェーズごとに出力されます。
  • UUU、SSS、RRRは、GCで使用した時間を示す数値(秒)で、それぞれ、ユーザーCPU時間、システムCPU時間、経過時間を示します。

【出力例】

説明の便宜のため、出力の冒頭に行番号を割り振っていますが、実際には出力されません。

1  [90.893s][info][gc             ] GC(45) Concurrent Cycle
2  [90.893s][info][gc,marking     ] GC(45) Concurrent Clear Claimed Marks
3  [90.893s][info][gc,marking     ] GC(45) Concurrent Clear Claimed Marks 0.054ms
4  [90.893s][info][gc,marking     ] GC(45) Concurrent Scan Root Regions
5  [90.899s][info][gc,marking     ] GC(45) Concurrent Scan Root Regions 5.549ms
6  [90.899s][info][gc,marking     ] GC(45) Concurrent Mark (90.899s)
7  [90.899s][info][gc,marking     ] GC(45) Concurrent Mark From Roots
8  [90.899s][info][gc,task        ] GC(45) Using 1 workers of 1 for marking
9  [91.875s][info][gc,marking     ] GC(45) Concurrent Mark From Roots 976.245ms
10 [91.875s][info][gc,marking     ] GC(45) Concurrent Preclean
11 [91.875s][info][gc,marking     ] GC(45) Concurrent Preclean 0.091ms
12 [91.875s][info][gc,marking     ] GC(45) Concurrent Mark (90.899s, 91.875s) 976.385ms
13 [91.876s][info][gc,start       ] GC(45) Pause Remark
14 [91.880s][info][gc,stringtable ] GC(45) Cleaned string and symbol table, strings: 13761 processed, 1 removed, symbols: 76801 processed, 1 removed
15 [91.880s][info][gc             ] GC(45) Pause Remark 1672M->1466M(2048M) 4.738ms
16 [91.880s][info][gc,cpu         ] GC(45) User=0.01s Sys=0.00s Real=0.00s
17 [91.880s][info][gc,marking     ] GC(45) Concurrent Rebuild Remembered Sets
18 [92.695s][info][gc,marking     ] GC(45) Concurrent Rebuild Remembered Sets 814.182ms
19 [92.695s][info][gc,start       ] GC(45) Pause Cleanup
20 [92.695s][info][gc             ] GC(45) Pause Cleanup 1467M->1467M(2048M) 0.552ms
21 [92.695s][info][gc,cpu         ] GC(45) User=0.00s Sys=0.00s Real=0.00s
22 [92.695s][info][gc,marking     ] GC(45) Concurrent Cleanup for Next Mark
23 [92.699s][info][gc,marking     ] GC(45) Concurrent Cleanup for Next Mark 3.935ms
24 [92.699s][info][gc             ] GC(45) Concurrent Cycle 1806.048ms

【意味】

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

  • JVM起動から90.893秒後に、Concurrent Cycleの処理が開始されました。
  • フェーズごとの処理時間は以下のとおりです。
    • Concurrent Clear Claimed Marks:0.054ms (行番号3)
    • Concurrent Scan Root Regions:5.549ms (行番号5)
    • Concurrent Mark From Roots:976.245ms (行番号9)
    • Concurrent Preclean:0.091ms (行番号11)
    • Pause Remark:4.738ms (行番号15)
    • Concurrent Rebuild Remembered Sets:814.182ms (行番号18)
    • Pause Cleanup:0.552ms (行番号20)
    • Concurrent Cleanup for Next Mark:3.935ms (行番号23)
  • Pause Remarkフェーズの処理時間4.738msとPause Cleanupフェーズの処理時間0.552msの合計である5.290msはアプリケーションを停止しました。それ以外のフェーズはアプリケーションの処理と並列でGCが行われました。
  • 「Concurrent Mark (90.899s, 91.875s) 976.385ms」のログはConcurrent Mark From Rootsフェーズの処理時間とConcurrent Precleanの処理時間、その関連処理の処理時間の合計が976.385msであることを意味しています。
  • Javaヒープ領域の使用量は、Pause Remark前の1672MBから、Pause Cleanup後の1467MBになり、Concurrent Cycleの期間は1806.048msでした。

2.3.3 Full GC

【出力形式】

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

[タイムスタンプ][info][gc,task        ] GC(GC通し番号) Using GCスレッド数 workers of 最大GCスレッド数 for full compaction  
[タイムスタンプ][info][gc,start       ] GC(GC通し番号) Pause Full (GC発生理由)  
[タイムスタンプ][info][gc,phases,start] GC(GC通し番号) Phase GCフェーズの通し番号: GCフェーズ名  
[タイムスタンプ][info][gc,stringtable ] GC(GC通し番号) Cleaned string and symbol table, strings: stringtableのエントリ数 processed, 削除したstringtableのエントリ数 removed, symbols: symbol tableのエントリ数 processed, 削除したsymbol tableのエントリ数 removed  
[タイムスタンプ][info][gc,phases      ] GC(GC通し番号) Phase GCフェーズの通し番号: GCフェーズ名 GC時間  
[タイムスタンプ][info][gc,heap        ] GC(GC通し番号) 領域名GC直前の使用領域数->GC直後の使用領域数(GC直後の領域数)  
[タイムスタンプ][info][gc,metaspace   ] GC(GC通し番号) Metaspace GC直前のMetaspace使用サイズ(GC直前のMetaspaceサイズ)->GC直後のMetaspace使用サイズ(GC直後のMetaspaceサイズ) NonClass: GC直前の使用サイズ(クラス以外の情報を格納するMetaspaceサイズ)->GC直後の使用サイズ(クラス以外の情報を格納するMetaspaceサイズ) Class: GC直前の使用サイズ(クラスの情報を格納するMetaspaceサイズ)->GC直後の使用サイズ(クラスの情報を格納するMetaspaceサイズ)  
[タイムスタンプ][info][gc             ] GC(GC通し番号) Pause Full (GC発生理由) GC直前のJavaヒープ使用サイズ->GC直後のJavaヒープ使用サイズ(Javaヒープサイズ) GC時間  
[タイムスタンプ][info][gc,cpu         ] GC(GC通し番号) User=UUUs Sys=SSSs Real=RRRs  
  • stringtableは、クラス名やメソッド名などをJVM内で管理するためのテーブルに関する情報であり、GCフェーズ1で出力されます。
  • GC直後の領域数は、Old領域とHumongous領域に対しては表示されません。
  • Metaspaceの情報では、(GC直後のMetaspaceサイズ)の部分までしか出力されず、領域の内訳情報が出力されない場合があります。
  • UUU、SSS、RRRは、GCで使用した時間を示す数値(秒)で、それぞれ、ユーザーCPU時間、システムCPU時間、経過時間を示します。

【出力例】

[221.643s][info][gc,task        ] GC(202) Using 4 workers of 4 for full compaction
[221.643s][info][gc,start       ] GC(202) Pause Full (G1 Evacuation Pause)
[221.648s][info][gc,phases,start] GC(202) Phase 1: Mark live objects
[221.986s][info][gc,stringtable ] GC(202) Cleaned string and symbol table, strings: 14112 processed, 2143 removed, symbols: 76845 processed, 0 removed
[221.987s][info][gc,phases      ] GC(202) Phase 1: Mark live objects 338.759ms
[221.987s][info][gc,phases,start] GC(202) Phase 2: Prepare for compaction
[222.062s][info][gc,phases      ] GC(202) Phase 2: Prepare for compaction 75.822ms
[222.062s][info][gc,phases,start] GC(202) Phase 3: Adjust pointers
[222.225s][info][gc,phases      ] GC(202) Phase 3: Adjust pointers 162.466ms
[222.225s][info][gc,phases,start] GC(202) Phase 4: Compact heap
[222.305s][info][gc,phases      ] GC(202) Phase 4: Compact heap 79.639ms
[222.310s][info][gc,heap        ] GC(202) Eden regions: 0->0(363)
[222.310s][info][gc,heap        ] GC(202) Survivor regions: 0->0(13)
[222.310s][info][gc,heap        ] GC(202) Old regions: 1846->950
[222.310s][info][gc,heap        ] GC(202) Humongous regions: 202->158
[222.310s][info][gc,metaspace   ] GC(202) Metaspace: 27028K(28032K)->26110K(28032K) NonClass: 24159K(24832K)->23378K(24832K) Class: 2868K(3200K)->2731K(3200K)
[222.310s][info][gc             ] GC(202) Pause Full (G1 Evacuation Pause) 2047M->1105M(2048M) 667.417ms
[222.310s][info][gc,cpu         ] GC(202) User=2.52s Sys=0.01s Real=0.66s

【意味】

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

  • Javaヒープ領域不足が原因で、202回目のGCが発生しました。
  • Full GCに利用可能な4つのGCスレッドのうち、4つのGCスレッドを使用しました。
  • GCフェーズことの処理時間は以下のとおりです。
    • Mark live objects: 338.759ms
    • Prepare for compaction: 75.822ms
    • Adjust pointers: 162.466ms
    • Compact heap: 79.639ms
  • 各領域の個数は以下のとおりです。
    • Eden領域: GC前の使用数=0、GC後の使用数=0、GC後に使用可能な数=363
    • Survivor領域: GC前の使用数=0、GC後の使用数=0、GC後に使用可能な数=13
    • Old領域: GC前の使用数=1846、GC後の使用数=950
    • Humongous領域: GC前の使用数=202、GC後の使用数=158
  • Metaspace領域の使用サイズは、27028KBから26110KBになり、GC後のMetaspaceサイズは28032KBです。
  • Javaヒープ全体では、使用量が2047MBから1105MBになり、処理時間は667.417msでした。
  • GCに要したユーザーCPU時間は2.52s、システムCPU時間は0.01sであり、実際の経過時間は0.66sでした。

3. おわりに

今回は、G1 GCログの読み方を紹介しました。GCに関する性能トラブルが発生している場合は、処理にかかった時間、GC前後のJavaヒープの使用状況などをログから分析することで、チューニングやプログラムの修正に役立てることができます。
本記事を、G1 GCを用いたアプリケーションの安定稼働に向けて参考にしてください。

こちらもおすすめ

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

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

お電話でのお問い合わせ

富士通コンタクトライン(総合窓口)

0120-933-200

受付時間:9時~12時および13時~17時30分
(土曜日・日曜日・祝日・当社指定の休業日を除く)

Webでのお問い合わせ

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

ページの先頭へ