ParallelGC ログの詳細な説明

JVM 起動パラメータ

JAVA_OPTS = "-Xms4G -Xmx4G -Xmn2G -XX:MetaspaceSize=512M -XX:MaxMetaspaceSize=512M -XX:+UseParallelGC -XX:+PrintGCDetails -Xloggc:/home/gc.log -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC"

JVM 起動パラメータの設定

• -XX:+PrintGCDetails: 各ガベージ コレクション後のヒープ メモリ使用量やコレクション前後のステータスなど、GC の詳細情報を出力します。
• -Xloggc:/home/gc.log: GC ログをコンソールに出力する代わりに、ファイル /home/gc.log に保存します。これにより、アプリケーションの実行後にログを分析できるようになります。
• -XX:+PrintGCDateStamps: ガベージ コレクションが発生した時刻を確認しやすくするために、各 GC ログ レコードに日付スタンプを追加します。
• -XX:+PrintGCTimeStamps: JVM 起動後の経過時間を各 GC ログに秒単位で追加します。
• -XX:+PrintHeapAtGC: 各世代 (若い世代、古い世代、メタスペース) のメモリ割り当てを含む、ガベージ コレクションの前後のヒープの詳細なステータスを出力します。
• -XX:+UseParallelGC: Parallel GC (並列ガベージ コレクター) を使用して、複数のスレッドで並列にガベージ コレクションを実行することでパフォーマンスを向上させます。

GC ログ スニペット

OpenJDK 64-Bit Server VM (25.342-b07) for linux-amd64 JRE (1.8.0_342-b07), built on Jul 16 2022 09:19:19 by "openjdk" with gcc 4.4.7 20120313 (Red Hat 4.4.7-23)
Memory: 4k page, physical 8388608k(8386904k free), swap 0k(0k free)
CommandLine flags: -XX:CompressedClassSpaceSize=528482304 -XX:InitialHeapSize=4294967296 -XX:MaxHeapSize=4294967296 -XX:MaxMetaspaceSize=536870912 -XX:MaxNewSize=2147483648 -XX:MetaspaceSize=536870912 -XX:NewSize=2147483648 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC

2024-09-24T10:43:44.094+0800: 21.703: Total time for which application threads were stopped: 0.0015655 seconds, Stopping threads took: 0.0000978 seconds
{Heap before GC invocations=11 (full 0):
 PSYoungGen      total 1494528K, used 1466389K [0x0000000790800000, 0x00000007f0800000, 0x00000007f0800000)
  eden space 1414656K, 100% used [0x0000000790800000,0x00000007e6d80000,0x00000007e6d80000)
  from space 79872K, 64% used [0x00000007eba00000,0x00000007eec85748,0x00000007f0800000)
  to   space 78336K, 0% used [0x00000007e6d80000,0x00000007e6d80000,0x00000007eba00000)
 ParOldGen       total 2621440K, used 72408K [0x00000006f0800000, 0x0000000790800000, 0x0000000790800000)
  object space 2621440K, 2% used [0x00000006f0800000,0x00000006f4eb60e0,0x0000000790800000)
 Metaspace       used 114761K, capacity 120350K, committed 120576K, reserved 1155072K
  class space    used 13324K, capacity 14260K, committed 14336K, reserved 1048576K
2024-09-24T10:43:44.149+0800: 21.759: [GC (Allocation Failure) [PSYoungGen: 1466389K->41915K(1492992K)] 1538798K->152295K(4114432K), 0.0591035 secs] [Times: user=0.16 sys=0.01, real=0.06 secs]
Heap after GC invocations=11 (full 0):
 PSYoungGen      total 1492992K, used 41915K [0x0000000790800000, 0x00000007f0800000, 0x00000007f0800000)
  eden space 1414656K, 0% used [0x0000000790800000,0x0000000790800000,0x00000007e6d80000)
  from space 78336K, 53% used [0x00000007e6d80000,0x00000007e966ee58,0x00000007eba00000)
  to   space 78336K, 0% used [0x00000007ebb80000,0x00000007ebb80000,0x00000007f0800000)
 ParOldGen       total 2621440K, used 110380K [0x00000006f0800000, 0x0000000790800000, 0x0000000790800000)
  object space 2621440K, 4% used [0x00000006f0800000,0x00000006f73cb088,0x0000000790800000)
 Metaspace       used 114761K, capacity 120350K, committed 120576K, reserved 1155072K
  class space    used 13324K, capacity 14260K, committed 14336K, reserved 1048576K
}
2024-09-24T10:43:44.209+0800: 21.818: Total time for which application threads were stopped: 0.0593724 seconds, Stopping threads took: 0.0000333 seconds


{Heap before GC invocations=906 (full 2):
 PSYoungGen      total 2065920K, used 2041627K [0x0000000760800000, 0x00000007e0800000, 0x00000007e0800000)
  eden space 2034688K, 100% used [0x0000000760800000,0x00000007dcb00000,0x00000007dcb00000)
  from space 31232K, 22% used [0x00000007de980000,0x00000007df046e10,0x00000007e0800000)
  to   space 31232K, 0% used [0x00000007dcb00000,0x00000007dcb00000,0x00000007de980000)
 ParOldGen       total 2097152K, used 2080736K [0x00000006e0800000, 0x0000000760800000, 0x0000000760800000)
  object space 2097152K, 99% used [0x00000006e0800000,0x000000075f7f8060,0x0000000760800000)
 Metaspace       used 176015K, capacity 189742K, committed 191104K, reserved 1218560K
  class space    used 19024K, capacity 21351K, committed 21632K, reserved 1048576K
2024-09-24T14:14:45.047+0800: 11571.644: [GC (Allocation Failure) [PSYoungGen: 2041627K->26414K(2061312K)] 4122363K->2109278K(4158464K), 0.0208053 secs] [Times: user=0.07 sys=0.00, real=0.02 secs]
Heap after GC invocations=906 (full 2):
 PSYoungGen      total 2061312K, used 26414K [0x0000000760800000, 0x00000007e0800000, 0x00000007e0800000)
  eden space 2034688K, 0% used [0x0000000760800000,0x0000000760800000,0x00000007dcb00000)
  from space 26624K, 99% used [0x00000007dcb00000,0x00000007de4cba70,0x00000007de500000)
  to   space 33792K, 0% used [0x00000007de700000,0x00000007de700000,0x00000007e0800000)
 ParOldGen       total 2097152K, used 2082863K [0x00000006e0800000, 0x0000000760800000, 0x0000000760800000)
  object space 2097152K, 99% used [0x00000006e0800000,0x000000075fa0be58,0x0000000760800000)
 Metaspace       used 176015K, capacity 189742K, committed 191104K, reserved 1218560K
  class space    used 19024K, capacity 21351K, committed 21632K, reserved 1048576K
}
{Heap before GC invocations=907 (full 3):
 PSYoungGen      total 2061312K, used 26414K [0x0000000760800000, 0x00000007e0800000, 0x00000007e0800000)
  eden space 2034688K, 0% used [0x0000000760800000,0x0000000760800000,0x00000007dcb00000)
  from space 26624K, 99% used [0x00000007dcb00000,0x00000007de4cba70,0x00000007de500000)
  to   space 33792K, 0% used [0x00000007de700000,0x00000007de700000,0x00000007e0800000)
 ParOldGen       total 2097152K, used 2082863K [0x00000006e0800000, 0x0000000760800000, 0x0000000760800000)
  object space 2097152K, 99% used [0x00000006e0800000,0x000000075fa0be58,0x0000000760800000)
 Metaspace       used 176015K, capacity 189742K, committed 191104K, reserved 1218560K
  class space    used 19024K, capacity 21351K, committed 21632K, reserved 1048576K
2024-09-24T14:14:45.068+0800: 11571.665: [Full GC (Ergonomics) [PSYoungGen: 26414K->0K(2061312K)] [ParOldGen: 2082863K->300700K(2097152K)] 2109278K->300700K(4158464K), [Metaspace: 176015K->174750K(1218560K)], 0.6404574 secs] [Times: user=1.88 sys=0.00, real=0.64 secs]
Heap after GC invocations=907 (full 3):
 PSYoungGen      total 2061312K, used 0K [0x0000000760800000, 0x00000007e0800000, 0x00000007e0800000)
  eden space 2034688K, 0% used [0x0000000760800000,0x0000000760800000,0x00000007dcb00000)
  from space 26624K, 0% used [0x00000007dcb00000,0x00000007dcb00000,0x00000007de500000)
  to   space 33792K, 0% used [0x00000007de700000,0x00000007de700000,0x00000007e0800000)
 ParOldGen       total 2097152K, used 300700K [0x00000006e0800000, 0x0000000760800000, 0x0000000760800000)
  object space 2097152K, 14% used [0x00000006e0800000,0x00000006f2da7140,0x0000000760800000)
 Metaspace       used 174750K, capacity 187618K, committed 191104K, reserved 1218560K
  class space    used 18827K, capacity 20997K, committed 21632K, reserved 1048576K
}

アプリケーションの一時停止時間

GC プロセス中、アプリケーションのすべてのスレッドは一時停止されます。これは「Stop-The-World」(STW) イベントと呼ばれます。一時停止時間は、アプリケーションのパフォーマンスと応答性に直接影響します。

ログの例:

2024-09-24T10:43:44.094+0800: 21.703: Total time for which application threads were stopped: 0.0015655 seconds, Stopping threads took: 0.0000978 seconds

アプリケーションスレッドが停止された合計時間:

• アプリケーション スレッドが一時停止された合計時間は、0.0015655 秒 (~1.57 ミリ秒) です。

スレッドの停止にかかった時間:

• スレッドの一時停止に費やした時間、ここでは 0.0000978 秒 (約 0.098 ミリ秒)。

GC (マイナー GC)

ログの例

2024-09-24T10:43:44.149+0800: 21.759: [GC (Allocation Failure) [PSYoungGen: 1466389K->41915K(1492992K)] 1538798K->152295K(4114432K), 0.0591035 secs]

• GC タイプ: メモリ割り当て失敗 (割り当て失敗) によってトリガーされるマイナー GC。
• 若い世代の変更: 1466389K から 41915K に、総容量 1492992K。
• ヒープメモリの合計変更: 1538798K から 152295K、合計容量 4114432K。
• 所要時間: 0.0591035 秒 (約 59 ミリ秒)。

フル GC

ログの例:

2024-09-24T14:14:45.068+0800: 11571.665: [Full GC (Ergonomics) [PSYoungGen: 26414K->0K(2061312K)] [ParOldGen: 2082863K->300700K(2097152K)] 2109278K->300700K(4158464K), [Metaspace: 176015K->174750K(1218560K)], 0.6404574 secs]

• GC タイプ: フル GC、JVM 適応メカニズム (人間工学) によってトリガーされます。
• 若い世代の変化: 26414K から 0K へ、若い世代が完全にリサイクルされたことを示します。
• 古い世代の変更: 2082863K から 300700K に削減され、多くのメモリが解放されました。
• ヒープメモリの合計変更: 2109278K から 300700K、合計容量 4158464K。
• メタスペースの変更: 176015K から 174750K に減少しました。
• 所要時間: 0.6404574 秒 (約 640 ミリ秒)。

ヒープメモリの詳細なステータス

-XX:+PrintHeapAtGC パラメーターを使用しているため、GC ログには、各メモリ領域の容量や使用状況など、各 GC の前後にヒープ メモリの詳細なステータスが出力されます。

ログの例:

Heap before GC invocations=11 (full 0):
 PSYoungGen      total 1494528K, used 1466389K [0x0000000790800000, 0x00000007f0800000, 0x00000007f0800000)
  eden space 1414656K, 100% used [0x0000000790800000,0x00000007e6d80000,0x00000007e6d80000)
  from space 79872K, 64% used [0x00000007eba00000,0x00000007eec85748,0x00000007f0800000)
  to   space 78336K, 0% used [0x00000007e6d80000,0x00000007e6d80000,0x00000007eba00000)
 ParOldGen       total 2621440K, used 72408K [0x00000006f0800000, 0x0000000790800000, 0x0000000790800000)
  object space 2621440K, 2% used [0x00000006f0800000,0x00000006f4eb60e0,0x0000000790800000)
 Metaspace       used 114761K, capacity 120350K, committed 120576K, reserved 1155072K
  class space    used 13324K, capacity 14260K, committed 14336K, reserved 1048576K

• PSYoungGen (若い世代):

  • 合計 (総容量): 1494528K。
  • 使用: 1466389K。
  • eden space (エデンエリア): 容量1414656K、使用率100%。
  • 宇宙から(生存者エリア): 容量79872K、使用率64%。
  • スペース (Survivor area) へ: 容量 78336K、未使用。

• ParOldGen (旧世代):

  • 合計 (総容量): 2621440K。
  • 使用: 72408K、使用率は約2%です。

• メタスペース:

  • 使用: 114761K。
  • 容量: 120350K。

JVM 起動パラメータと GC ログの対応

JVM 起動パラメータを手動で設定しているため、GC ログには詳細な分析を容易にするより詳細な情報が含まれています。

• メモリの割り当てと使用量:

  • -XX:+PrintHeapAtGC を使用すると、各 GC の前後でヒープ メモリの状態を表示し、各領域のメモリ割り当てと使用状況を把握できます。

• タイムスタンプ情報:

  • -XX:+PrintGCDateStamps および -XX:+PrintGCTimeStamps は、GC イベントの時点と間隔の分析を容易にする正確な時間情報を提供します。

• GC イベントの詳細:

  • -XX:+PrintGCDetails は、GC イベントのタイプ、トリガーの理由、メモリのリサイクル ステータス、消費時間などの詳細情報を出力します。

以上がParallelGC ログの詳細な説明の詳細内容です。詳細については、PHP 中国語 Web サイトの他の関連記事を参照してください。