ParallelGC 日志详解

心靈之曲

发布时间：2024-09-25 10:24:16

427人浏览过

来源于dev.to

转载

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

日志示例:

iWebShop开源商城系统

iWebShop是一款基于PHP语言及MYSQL数据库开发的B2B2C多用户开源免费的商城系统，系统支持自营和多商家入驻、集成微信商城、手机商城、移动端APP商城、三级分销、视频电商直播、微信小程序等于一体，它可以承载大数据量且性能优良，还可以跨平台，界面美观功能丰富是电商建站首选源码。iWebShop开源商城系统 v5.14 更新日志：新增商品编辑页面规格图片上传优化商品详情页面规格图片与主图切

下载

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 事件的类型、触发原因、内存回收情况和耗时等详细信息。