Javaの詳細なガベージコレクション

1. 概要

このチュートリアルでは、* Javaアプリケーションで詳細なガベージコレクションを有効にする方法を見ていきます*。 まず、冗長なガベージコレクションとは何か、なぜそれが役立つのかを紹介します。
次に、いくつかの異なる例を見て、利用可能なさまざまな構成オプションについて学習します。 さらに、*詳細ログの出力の解釈方法にも焦点を当てます。*
ガベージコレクション(GC)および利用可能なさまざまな実装の詳細については、https://www.baeldung.com/jvm-garbage-collectors [Java Garbage Collectors]の記事をご覧ください。

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

*多くの問題、特にメモリの問題をチューニングおよびデバッグする際には、詳細なガベージコレクションロギングをオンにすることがしばしば必要です。 実際、アプリケーションの正常性を厳密に監視するには、常にJVMのガベージコレクションのパフォーマンスを監視する必要があると主張する人もいます。
後で見るように、GCログは、アプリケーションのヒープおよびGC構成の潜在的な改善を明らかにするための非常に重要なツールです。 * GCが発生するたびに、GCログはその結果と期間に関する正確なデータを提供します。*
時間が経つにつれて、この情報の分析は、動作またはアプリケーションをよりよく理解し、アプリケーションのパフォーマンスを調整するのに役立ちます。 さらに、最適なヒープサイズ、他のJVMオプション、代替GCアルゴリズムを指定することにより、GCの頻度と収集時間を最適化するのに役立ちます。*

2.1. 簡単なJavaプログラム

GCログを有効にして解釈する方法を示すために、簡単なJavaプログラムを使用します。
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に設定しましたが、もちろん、https://www.baeldung.com/jvm-parameters [JVM parameters]を調整できます。

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つのFull GC、3つのクリーニングYoung世代が行われたことがわかります*。

3.2. 詳細な出力

出力行をより詳細に分解して、何が起こっているのかを正確に理解しましょう。
  1. GC_または_Full GCガベージコレクションのタイプ、_GC_または
    _Full GC_マイナーまたはフルガベージコレクションを区別します

  2. (割り当てエラー)_または(System.gc())_ –の原因
    コレクション– 割り当ての失敗は、オブジェクトを割り当てるためにEdenにスペースが残っていないことを示します

  3. 279616K→ 146232K – GC前後の占有ヒープメモリ、
    それぞれ(矢印で区切られています)

  4. (1013632K) –ヒープの現在の容量

  5. 0.3318607 secs – 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_とこの追加の引数を組み合わせて、ログでさらに詳細な情報を取得する方法を説明します。

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(割り当てエラー)279616K→ 146232K(1013632K)、0.3627492秒]

    前と同様に、行を部分に分けます。
    1. DefNew –使用されるガベージコレクターの名前。 これはそれほど明白ではない
      名前は、シングルスレッドのマークコピーストップザワールドガベージコレクターを表し、Young世代をクリーンアップするために使用されます

    2. 279616K→ 34944K –若い世代の前後の使用
      コレクション

    3. (314560K) –若い世代の合計サイズ

    4. 0.3626923秒–秒単位の期間

    5. _ [Times:user = 0.33 sys = 0.03、real = 0.36 secs_] – GCの期間
      さまざまなカテゴリで測定されるイベント

      それでは、さまざまなカテゴリについて説明しましょう。
  • user –ガベージコレクターによって消費された合計CPU時間

  • sys – OS呼び出しまたはシステムイベントの待機に費やされた時間

  • real –これは、他のユーザーが使用するタイムスライスを含むすべての経過時間です。
    プロセス

    *常に単一のスレッドのみを使用するSerial Garbage Collectorを使用してサンプルを実行しているため、リアルタイムはユーザー時間とシステム時間の合計に等しくなります。*

5.2。 フルGCの解釈

この最後から2番目の例では、システムコールによってトリガーされたメジャーコレクション(Full GC)で、使用されたコレクターは_Tenured_でした。
表示される最後の追加情報は、_Metaspace_の同じパターンに従った内訳です。
[Metaspace: 2624K->2624K(1056768K)], 0.5580738 secs]
  • _Metaspace_は、Java 8で導入された新しいlink:/java-permgen-metaspace [メモリスペース]であり、ネイティブメモリの領域です。 *

5.3。 Javaヒープ内訳分析

*出力の最後の部分には、メモリの各部分のメモリフットプリントの概要を含むヒープの内訳が含まれています*。
Edenスペースのフットプリントが35%、Tenuredのフットプリントが52%であることがわかります。 メタデータスペースとクラススペースの概要も含まれています。
上記の例から、* GCイベント中にJVM内のメモリ消費で何が起こっていたかを正確に理解できるようになりました。*

6. 日時情報の追加

日付と時刻の情報がなければ、完全なログは完成しません。
*この追加情報は、GCログデータを他のソースからのデータと相関させる必要がある場合に非常に役立つ場合があります。または、単に検索を容易にするのに役立ちます。*
ログに表示される日付と時刻の情報を取得するためにアプリケーションを実行するときに、次の2つの引数を追加できます。
-XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps
各行は、JVMが開始されてから秒単位で渡されるリアルタイムを反映するタイムスタンプが後に続く、書き込まれた絶対日付と時刻で始まります。
2018-12-11T02:55:23.518+0100: 2.601: [GC (Allocation ...

7. ファイルへのロギング

すでに見たように、デフォルトではGCログは_stdout_に書き込まれます。 より実用的な解決策は、出力ファイルを指定することです。
*引数_-Xloggc:<file> _を使用してこれを行うことができます。ここで、_file_は出力ファイルへの絶対パスです。*
-Xloggc:/path/to/file/gc.log

8. Java 9以降の言葉

GCロギングの世界では、_-XX:+ PrintGC._の別の議論に出くわすでしょう。Java8では、_-- verbose:gc_はc_XX:+ PrintGC_の正確なエイリアスです。 ただし、_- verbose:gc_は標準オプションですが、_- XX:+ PrintGC_は標準オプションではありません。
また、統合ログオプション_-Xlog:gc._を優先して_-XX:+ PrintGC_がJava 9で非推奨になったことにも注意する必要がありますが、_– verbose:gc_はJDK 9および10でも引き続き機能します。
統合JVMロギングの詳細については、https://openjdk.java.net/jeps/158[JEP 158 standard]を参照してください。

9. A GCログを分析するツール

テキストエディタを使用してGCログを分析するのは時間がかかり、かなり面倒です。 JVMバージョンと使用されているGCアルゴリズムによって、GCログ形式は異なる場合があります。
ガベージコレクションログを分析し、ガベージコレクションの潜在的な問題に関する多くのメトリックを提供し、さらにこれらの問題の潜在的な解決策を提供する、非常に優れた無料のグラフィカル分析ツールがあります。
http://gceasy.io/[Universal GC Log Analyzer]を絶対にチェックしてください!

10. 結論

要約すると、このチュートリアルでは、Javaの詳細なガベージコレクションについて詳しく説明しました。
まず、冗長なガベージコレクションとは何か、なぜそれを使用したいのかを紹介することから始めました。 次に、単純なJavaアプリケーションを使用したいくつかの例を見てみました。 いくつかのより詳細な例と出力の解釈方法を調べる前に、最も単純な形式でGCロギングを有効にすることから始めました。
最後に、時刻と日付の情報をログに記録するためのいくつかの追加オプションと、ログファイルに情報を書き込む方法を検討しました。
コード例はhttps://github.com/eugenp/tutorials/tree/master/core-java-modules/core-java-perf[on GitHub]にあります。