JavaのVerboseガベージコレクション

投稿日: 2019-10-19 2022-10-23
タグ: Garbage Collection, Java, JVM

1. 概要

このチュートリアルでは、Javaアプリケーションで詳細なガベージコレクションをオンにする方法を見ていきます。まず、冗長なガベージコレクションとは何か、なぜそれが役立つのかを紹介します。

次に、いくつかの異なる例を見て、利用可能なさまざまな構成オプションについて学習します。さらに、詳細ログの出力を解釈する方法にも焦点を当てます。

ガベージコレクション（GC）と利用可能なさまざまな実装の詳細については、Javaガベージコレクターに関する記事をご覧ください。

2. Verboseガベージコレクションの簡単な紹介

多くの問題、特にメモリの問題を調整およびデバッグする場合、詳細なガベージコレクションロギングをオンにする必要があります。実際、アプリケーションの状態を厳密に監視するには、JVMのガベージコレクションのパフォーマンスを常に監視する必要があると主張する人もいます。

これから説明するように、GCログは、アプリケーションのヒープおよびGC構成に対する潜在的な改善を明らかにするための非常に重要なツールです。 発生するGCごとに、GCログはその結果と期間に関する正確なデータを提供します。

時間の経過とともに、この情報の分析は、アプリケーションの動作をよりよく理解し、アプリケーションのパフォーマンスを調整するのに役立ちます。さらに、最適なヒープサイズ、他のJVMオプション、および代替GCアルゴリズムを指定することにより、GCの頻度と収集時間を最適化するのに役立ちます。

2.1. 単純なJavaプログラム

簡単なJavaプログラムを使用して、GCログを有効にして解釈する方法を示します。

public class Application {

    private static Map<String, String> stringContainer = new HashMap<>();

    public static void main(String[] args) {
        System.out.println("Start of program!");
        String stringWithPrefix = "stringWithPrefix";

        // Load Java Heap with 3 M java.lang.String instances
        for (int i = 0; i < 3000000; i++) {
            String newString = stringWithPrefix + i;
            stringContainer.put(newString, newString);
        }
        System.out.println("MAP size: " + stringContainer.size());

        // Explicit GC!
        System.gc();

        // Remove 2 M out of 3 M
        for (int i = 0; i < 2000000; i++) {
            String newString = stringWithPrefix + i;
            stringContainer.remove(newString);
        }

        System.out.println("MAP size: " + stringContainer.size());
        System.out.println("End of program!");
    }
}

上記の例でわかるように、この単純なプログラムは300万のStringインスタンスをMapオブジェクトにロードします。次に、 System.gc（）を使用してガベージコレクターを明示的に呼び出します。

最後に、Mapから200万個のStringインスタンスを削除します。また、 System.out.println を明示的に使用して、出力の解釈を容易にします。

次のセクションでは、GCロギングをアクティブ化する方法を説明します。

3. 「単純な」GCロギングのアクティブ化

プログラムを実行し、JVM起動引数を介して冗長GCを有効にすることから始めましょう。

-XX:+UseSerialGC -Xms1024m -Xmx1024m -verbose:gc

ここでの重要な引数は-verbose：gcです。これは、最も単純な形式でガベージコレクション情報のロギングをアクティブにします。デフォルトでは、GCログは stdout に書き込まれ、すべての若い世代のGCとすべての完全なGCの行を出力する必要があります。

この例では、引数 -XX：+ UseSerialGC を使用して、最も単純なGC実装であるシリアルガベージコレクターを指定しました。

また、最小および最大のヒープサイズを1024mbに設定しましたが、もちろん、調整できるJVMパラメーターは他にもあります。

3.1. 冗長出力の基本的な理解

次に、単純なプログラムの出力を見てみましょう。

Start of program!
[GC (Allocation Failure)  279616K->146232K(1013632K), 0.3318607 secs]
[GC (Allocation Failure)  425848K->295442K(1013632K), 0.4266943 secs]
MAP size: 3000000
[Full GC (System.gc())  434341K->368279K(1013632K), 0.5420611 secs]
[GC (Allocation Failure)  647895K->368280K(1013632K), 0.0075449 secs]
MAP size: 1000000
End of program!

上記の出力では、JVM内で何が起こっているかについての多くの有用な情報をすでに見ることができます。

最初は、この出力はかなり気が遠くなるように見えるかもしれませんが、今度はそれを段階的に見ていきましょう。

まず、 4つのコレクションが行われたことがわかります。1つはフルGCで、3つは若い世代のクリーニングです。

3.2. 詳細な詳細出力

何が起こっているのかを正確に理解するために、出力行をより詳細に分解してみましょう。

GCまたはフルGC– ガベージコレクションのタイプ（マイナーまたはフルガベージコレクションを区別するためのGCまたはフルGC）
（割り当ての失敗）または（System.gc（）） –収集の原因– 割り当ての失敗は、オブジェクトを割り当てるためのスペースがEdenに残っていないことを示します[ X180X]
279616K-> 146232K – GCの前後でそれぞれ占有されているヒープメモリ（矢印で区切られています）
（1013632K） –ヒープの現在の容量
0.3318607秒–秒単位のGCイベントの期間

したがって、最初の行をとると、 279616K-> 146232K（1013632K）は、GCが占有ヒープメモリを279616Kから146232Kに減らしたことを意味します。 GC時のヒープ容量は1013632Kで、GCは0.3318607秒かかりました。

ただし、単純なGCロギング形式は便利ですが、提供される詳細は限られています。 たとえば、GCがオブジェクトを若い世代から古い世代に移動したかどうか、または各コレクションの前後の若い世代の合計サイズはわかりません。

そのため、詳細なGCロギングは単純なものよりも便利です。

4. 「詳細な」GCロギングのアクティブ化

詳細なGCロギングをアクティブにするには、引数-XX：+ PrintGCDetailsを使用します。これにより、次のような各GCの詳細がわかります。

各GC前後の老若男女のサイズ
老若男女でGCが発生するのにかかる時間
すべてのGCでプロモートされるオブジェクトのサイズ
合計ヒープのサイズの要約

次の例では、 -verbose：gc とこの追加の引数を組み合わせて、ログにさらに詳細な情報を取り込む方法を示します。

-XX：+ PrintGCDetailsフラグはJava9で非推奨になり、新しい統合ロギングメカニズムが採用されたことに注意してください（これについては後で詳しく説明します）。ともかく、 -XX：+ PrintGCDetailsに相当する新しいものは、-Xlog：gc*オプションです。

5. 「詳細な」詳細な出力の解釈

サンプルプログラムをもう一度実行してみましょう。

-XX:+UseSerialGC -Xms1024m -Xmx1024m -verbose:gc -XX:+PrintGCDetails

今回の出力はかなり冗長です。

Start of program!
[GC (Allocation Failure) [DefNew: 279616K->34944K(314560K), 0.3626923 secs] 279616K->146232K(1013632K), 0.3627492 secs] [Times: user=0.33 sys=0.03, real=0.36 secs] 
[GC (Allocation Failure) [DefNew: 314560K->34943K(314560K), 0.4589079 secs] 425848K->295442K(1013632K), 0.4589526 secs] [Times: user=0.41 sys=0.05, real=0.46 secs] 
MAP size: 3000000
[Full GC (System.gc()) [Tenured: 260498K->368281K(699072K), 0.5580183 secs] 434341K->368281K(1013632K), [Metaspace: 2624K->2624K(1056768K)], 0.5580738 secs] [Times: user=0.50 sys=0.06, real=0.56 secs] 
[GC (Allocation Failure) [DefNew: 279616K->0K(314560K), 0.0076722 secs] 647897K->368281K(1013632K), 0.0077169 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
MAP size: 1000000
End of program!
Heap
 def new generation   total 314560K, used 100261K [0x00000000c0000000, 0x00000000d5550000, 0x00000000d5550000)
  eden space 279616K,  35% used [0x00000000c0000000, 0x00000000c61e9370, 0x00000000d1110000)
  from space 34944K,   0% used [0x00000000d3330000, 0x00000000d3330188, 0x00000000d5550000)
  to   space 34944K,   0% used [0x00000000d1110000, 0x00000000d1110000, 0x00000000d3330000)
 tenured generation   total 699072K, used 368281K [0x00000000d5550000, 0x0000000100000000, 0x0000000100000000)
   the space 699072K,  52% used [0x00000000d5550000, 0x00000000ebcf65e0, 0x00000000ebcf6600, 0x0000000100000000)
 Metaspace       used 2637K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 283K, capacity 386K, committed 512K, reserved 1048576K

単純なGCログからすべての要素を認識できるはずです。しかし、いくつかの新しいアイテムがあります。

次のセクションで青色で強調表示されている出力の新しい項目について考えてみましょう。

5.1. 若い世代のマイナーGCの解釈

まず、マイナーGCで新しいパーツを分析します。

[GC（割り当て失敗） [DefNew：279616K-> 34944K（314560K）、0.3626923秒] 279616K-> 146232K（1013632K）、0.3627492秒] [時間：user = 0.33 sys = 0.03、実数=0.36秒]

前と同じように、行をいくつかの部分に分割します。

DefNew –使用されたガベージコレクターの名前。このあまり明白ではない名前は、シングルスレッドのマークコピーストップザワールドガベージコレクターを表し、若い世代をクリーンアップするために使用されるものです
279616K-> 34944K –収集前後の若い世代の使用法
（314560K） –若い世代の合計サイズ
0.3626923秒–秒単位の期間
[Times：user = 0.33 sys = 0.03、real = 0.36 secs ] –さまざまなカテゴリで測定されたGCイベントの期間

次に、さまざまなカテゴリについて説明します。

user –ガベージコレクターによって消費された合計CPU時間
sys –OS呼び出しまたはシステムイベントの待機に費やされた時間
real –これは、他のプロセスによって使用されるタイムスライスを含むすべての経過時間です

常に単一のスレッドのみを使用するシリアルガベージコレクターを使用して例を実行しているため、リアルタイムはユーザー時間とシステム時間の合計に等しくなります。

5.2. フルGCの解釈

この最後から2番目の例では、システムコールによってトリガーされたメジャーコレクション（フルGC）の場合、使用されたコレクターはTenuredでした。

最後に表示される追加情報は、Metaspaceの同じパターンに従った内訳です。

[Metaspace: 2624K->2624K(1056768K)], 0.5580738 secs]

Metaspace は、Java 8で導入された新しいメモリスペースであり、ネイティブメモリの領域です。

5.3. Javaヒープ内訳分析

出力の最後の部分には、メモリの各部分のメモリフットプリントの概要を含むヒープの内訳が含まれます。

Edenスペースには35% footprintがあり、Tenuredには52% footprintがあることがわかります。メタデータスペースとクラススペースの概要も含まれています。

上記の例から、GCイベント中にJVM内のメモリ消費で何が起こっていたかを正確に理解できるようになりました。

6. 日付と時刻の情報を追加する

日付と時刻の情報がないと、適切なログは完成しません。

この追加情報は、GCログデータを他のソースからのデータと関連付ける必要がある場合に非常に役立ちます。または、単に検索を容易にするのに役立ちます。

アプリケーションを実行してログに表示される日付と時刻の情報を取得するときに、次の2つの引数を追加できます。

-XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps

各行は、書き込まれた絶対日時で始まり、JVMが開始されてから秒単位で渡されたリアルタイムを反映するタイムスタンプが続きます。

2018-12-11T02:55:23.518+0100: 2.601: [GC (Allocation ...

これらのチューニングフラグはJava9で削除されていることに注意してください。新しい選択肢は次のとおりです。

-Xlog:gc*::time

7. ファイルへのログ記録

すでに見てきたように、デフォルトでは、GCログはstdoutに書き込まれます。より実用的な解決策は、出力ファイルを指定することです。

引数を使用してこれを行うことができます -Xloggc： どこファイル出力ファイルへの絶対パスです。

-Xloggc:/path/to/file/gc.log

他のチューニングフラグと同様に、Java 9は-Xloggcフラグを廃止し、新しい統合ロギングを採用しました。具体的には、ファイルにログを記録するための代替手段は次のとおりです。

-Xlog:gc:/path/to/file/gc.log

8. Java 9：統合JVMロギング

Java 9以降、GC関連のチューニングフラグのほとんどは非推奨になり、統合ロギングオプション -Xlog：gcが採用されました。ただし、 – verbose：gc オプションは、Java9以降のバージョンでも機能します。

たとえば、Java 9の時点で、新しい統合ロギングシステムの -verbose：gcフラグに相当するものは次のとおりです。

-Xlog:gc

これにより、すべての情報レベルのGCログが標準出力に記録されます。使用することも可能です -Xlog：gc = ログレベルを変更するための構文。たとえば、すべてのデバッグレベルのログを表示するには、次のようにします。

-Xlog:gc=debug

前に見たように、出力先を変更することができます -Xlog：gc = ： 構文。デフォルトでは、outputはstdoutですが、stderrまたはファイルに変更することもできます。

-Xlog:gc=debug:file=gc.txt

また、デコレータを使用して、出力にさらにいくつかのフィールドを追加することもできます。例えば：

-Xlog:gc=debug::pid,time,uptime

ここでは、各ログステートメントにプロセスID、稼働時間、および現在のタイムスタンプを出力しています。

統合JVMロギングのその他の例については、JEP158標準を参照してください。

9.9。 A GCログを分析するためのツール

テキストエディタを使用してGCログを分析するのは、時間がかかり、非常に面倒な場合があります。 JVMのバージョンと使用されるGCアルゴリズムに応じて、GCログ形式が異なる場合があります。

ガベージコレクションログを分析し、潜在的なガベージコレクションの問題に関する多くのメトリックを提供し、これらの問題の潜在的な解決策を提供する、非常に優れた無料のグラフィカル分析ツールがあります。

ユニバーサルGCログアナライザーをぜひチェックしてください！

10. 結論

要約すると、このチュートリアルでは、Javaでの詳細なガベージコレクションについて詳しく説明しました。

まず、冗長なガベージコレクションとは何か、なぜそれを使用するのかを紹介することから始めました。次に、単純なJavaアプリケーションを使用していくつかの例を調べました。いくつかのより詳細な例と出力の解釈方法を検討する前に、最も単純な形式でGCロギングを有効にすることから始めました。

最後に、日時情報をログに記録するためのいくつかの追加オプションと、ログファイルに情報を書き込む方法について説明しました。

コード例は、GitHubのにあります。

getdocs

13036