为什么 G1 垃圾收集器卸载时间会随着时间的推移而增加?

Why are G1 garbage collector Unloading times increasing over time?

当 运行 Solaris (SPARC) 下的 Glassfish 和 JDK 8u172 时,我在使用 G1 垃圾收集器时遇到了一个奇怪的行为,Unloading 时间 Remark 阶段很长,并且随着时间的推移而增加。

这是应用程序服务器刚启动后的日志摘录:

2018-10-18T10:08:28.362+0200: 9528.430: [GC remark 2018-10-18T10:08:28.362+0200: 9528.430: [Finalize Marking, 0.0012164 secs] 2018-10-18T10:08:28.363+0200: 9528.431: [GC ref-proc, 0.1783250 secs] 2018-10-18T10:08:28.541+0200: 9528.609: [Unloading, 1.4087725 secs], 1.5954223 secs] [Times: user=10.79 sys=0.04, real=1.60 secs]

几天后:

2018-10-22T20:24:52.070+0200: 392111.556: [GC remark 2018-10-22T20:24:52.070+0200: 392111.556: [Finalize Marking, 0.0010811 secs] 2018-10-22T20:24:52.072+0200: 392111.557: [GC ref-proc, 0.1432306 secs] 2018-10-22T20:24:52.215+0200: 392111.701: [Unloading, 5.4160564 secs], 5.5672543 secs] [Times: user=41.16 sys=0.06, real=5.57 secs]

如您所见,Unloading 时间从 1.6 秒增加到 5.6 秒。

这是 Unloading 次随时间变化的图表:

如您所见,随着时间的推移,它或多或少呈线性增长。

以下是相关的命令行标志:

-XX:+AlwaysPreTouch -XX:GCLogFileSize=10485760 -XX:InitialHeapSize=8589934592 -XX:MaxHeapSize=8589934592 -XX:MetaspaceSize=536870912 -XX:NumberOfGCLogFiles=5 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UnlockDiagnosticVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:+UseGCLogFileRotation -XX:+UseLargePages -XX:+UseLargePagesInMetaspace

标记 -XX:+UseLargePagesInMetaspace 是在阅读 this blog post, but unfortunately it doesn't solve the problem. I also had a look at this other blog post and this question 后添加的,但不幸的是,none 的建议解决方案似乎适用于这种情况。

当 Glassfish 服务器 运行 在其他操作 Systems/architectures 下时,我无法重现此错误。

这是 JDK 中的错误:JDK-8199406 : Performance drop with Java JDK 1.8.0_162-b32

根据错误描述和 this discussion thread,此错误:

  • 是 JDK 8u161 中引入的影响垃圾收集的回归
  • 特定于 Solaris:“有关于 Solaris SPARC 64 性能下降的报告”; "在 x86 上它真的很快。"
  • 增加 class- 卸载时间:“这是在 8u161 中引入的回归,将 class- 卸载时间从平均 0.65 秒增加到 10 秒客户的秒数。"
  • 固定在JDK 8u181/8u182.

迁移到 JDK 8u192 修复了错误,Unloading 时间现在小得多并且常量 :

2018-10-24T11:57:48.479+0200: 96295.786: [GC remark 2018-10-24T11:57:48.480+0200: 96295.786: [Finalize Marking, 0.0012370 secs] 2018-10-24T11:57:48.481+0200: 96295.787: [GC ref-proc, 0.0960026 secs] 2018-10-24T11:57:48.577+0200: 96295.883: [Unloading, 0.2760147 secs], 0.3796341 secs] [Times: user=1.51 sys=0.02, real=0.38 secs]