ParallelGC 日志详解

一分耕耘，一分收获！既然都打开这篇《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 日志详解》的内容了。个人认为，基础知识的学习和巩固，是为了更好的将其运用到项目中，欢迎关注golang学习网公众号，带你了解更多关于的知识点！