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: 為每次 GC 日誌新增 JVM 啟動後經過的時間，以秒為單位。
• -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

Total time for which application threads were stopped：

• 應用程式執行緒被暫停的總時間，這裡是 0.0015655 秒（約 1.57 毫秒）。

Stopping threads took：

• 暫停執行緒所花費的時間，這裡是 0.0000978 秒（約 0.098 毫秒）。

GC（Minor GC）

日誌範例

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

• GC 類型：Minor GC，因記憶體分配失敗（Allocation Failure）觸發。
• 年輕世代變化：從 1466389K 降至 41915K，總容量 1492992K。
• 堆疊記憶體總變化：從 1538798K 降至 152295K，總容量 4114432K。
• 耗時：0.0591035 秒（約 59 毫秒）。

Full 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 類型：Full GC，觸發原因是 JVM 自適應機制（Ergonomics）。
• 年輕代變化：從 26414K 降至 0K，表示年輕代已完全回收。
• 老年代變化：從 2082863K 降至 300700K，釋放了大量記憶體。
• 堆疊記憶體總變化：從 2109278K 降至 300700K，總容量 4158464K。
• Metaspace 變化：從 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（年輕代）：

  • total（總容量）：1494528K。
  • used（已使用）：1466389K。
  • eden space（Eden 區）：容量 1414656K，使用率 100%。
  • from space（Survivor 區）：容量 79872K，使用率 64%。
  • to space（Survivor 區）：容量 78336K，未使用。

• ParOldGen（老年代）：

  • total（總容量）：2621440K。
  • used（已使用）：72408K，使用率約 2%。

• Metaspace（元空間）：

  • used（已使用）：114761K。
  • capacity（容量）：120350K。

JVM 啟動參數與 GC 日誌的對應關係

由於手動設定了 JVM 啟動參數，GC 日誌中包含了更詳細的信息，這些資訊有助於深入分析：

• 記憶體分配與使用：

  • 透過 -XX:+PrintHeapAtGC，可以查看每次 GC 前後的堆記憶體狀態，以了解各區域的記憶體分配和使用率。

• 時間戳資訊：

  • -XX:+PrintGCDateStamps 和 -XX:+PrintGCTimeStamps 提供了精確的時間信息，以便於分析 GC 事件的時間點和間隔。

• GC 事件的詳細資訊：

  • -XX:+PrintGCDetails 輸出了 GC 事件的類型、觸發原因、記憶體回收和耗時等詳細資訊。

以上是ParallelGC 日誌詳解的詳細內容。更多資訊請關注PHP中文網其他相關文章！