首页 > 图灵资讯 > 技术篇>正文

ParallelGC 日志详解

2024-09-29 20:25:24

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 [0x0000000790000,0x000007e6d800000,0x00000007e6d80000)
  from space 79872k, 64% used [0x000007eba00000，0x000007ec85748，0x00000007f08000000)
  to   space 78336k, 0% used [0x00000000007e6d80000000000000000x00000000007eba000000000)
 paroldgen       total 2621440k, used 72408k [0x00000006f0800000, 0x0000000790800000, 0x0000000790800000)
  object space 2621440k, 2% used [0x00000006f080000000000000000000000006f4eb60e0，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 [0x0000000007e6d80000000000x000000007e96e58，0x0000007eba0000000)
  to   space 78336k, 0% used [0x000007eb80000000000007eb800000000000000000000000000000000000007eb8000000000000000000000000000000000000000000000000000000000000000007eb8000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
 paroldgen       total 2621440k, used 110380k [0x00000006f0800000, 0x0000000790800000, 0x0000000790800000)
  object space 2621440k, 4% used [00000006f08000000000000000000000000006f73cb088，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 [0x0000000760000,0x00000007dcb0000,0x00000007dcb00000)
  from space 31232k, 22% used [0x000007de9800000000007df046e10，0x000000007de980000000
  to   space 31232k, 0% used [0x0000007dcb00000，0x000007dcb000000，0x00000007de9800000)
 paroldgen       total 2097152k, used 2080736k [0x00000006e0800000, 0x0000000760800000, 0x0000000760800000)
  object space 2097152k, 99% used [0x00000006e08000,0x0000075f8060,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,0x00000007600000,0x00000007dcb000000)
  from space 26624k, 99% used [0x0000000007dcb00000000000x00000007de4cba70000000007de50000000)
  to   space 33792k, 0% used [0x000007de7000000000007de700000000000000000000000000007de70000000000000000000007de7de70000000000000000000000000000000000000000000000000000000000000007de7de7de7000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000007d7d7d7de7de7de7de7de7de7de7de7de
 paroldgen       total 2097152k, used 2082863k [0x00000006e0800000, 0x0000000760800000, 0x0000000760800000)
  object space 2097152k, 99% used [0000000000000000000000000000000000000075fa0be58，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 [0x000007dcb00000，0x000007de4cba70，0x0000007de5000000)
  to   space 33792k, 0% used [0x000007de7000000000007de700000000000000000000000000007de70000000000000000000007de7de70000000000000000000000000000000000000000000000000000000000000007de7de7de7000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000007d7d7d7de7de7de7de7de7de7de7de7de
 paroldgen       total 2097152k, used 2082863k [0x00000006e0800000, 0x0000000760800000, 0x0000000760800000)
  object space 2097152k, 99% used 0x00000006e0800000000000000075fa0be58，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 [0x00000760000，0x0000076000000007dcb00000000
  from space 26624k, 0% used [0x00000000007dcb00000000000000000000000007dcb00000000007de5000000000)
  to   space 33792k, 0% used [0000007de7000000，0000007de7000000，0x00000007e0800000)
 paroldgen       total 2097152k, used 300700k [0x00000006e0800000, 0x0000000760800000, 0x0000000760800000)
  object space 2097152k, 14% used [0x000006e000000006f2da7140000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
 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 [0x0000070008000000007e6d80000000000000000000000000007e6d800000000000000000000000000000000000000000000000000000000000000000007e6e6d8000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000700000000000000000000000000000000000000000000000000070000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
  from space 79872K, 64% used [0x000007eba00000，0x000007ec85748，0x00000007f08000000)
  to   space 78336K, 0% used 0x0000007e6d8000,0x00000007e6d8000,0x00000000007eba00000)
 ParOldGen       total 2621440K, used 72408K [0x00000006f0800000, 0x0000000790800000, 0x0000000790800000)
  object space 2621440K, 2% used [0x000006f0800000000006f4eb60e00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000006ffffffffffffffff400000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
 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 详情请关注图灵教育的其他相关文章！

上一篇 右移非零值：公共数组面试问题 2
下一篇 返回列表

文章素材均来源于网络，如有侵权，请联系管理员删除。