java - G1 Collector 每秒执行 50 次

Question

在 G1 中使用 Java 1.6.0_45 我有一个几乎无限期运行 G1 收集器的应用程序。除此之外，这似乎浪费了一些 CPU，它还以我能找到的最低设置快速填充了我的 gc 日志。

我想知道这里发生了什么。正常吗？

这些是我的 JVM 标志：

-XX:ParallelGCThreads=4
-XX:+DisableExplicitGC
-XX:+PrintAdaptiveSizePolicy
-XX:MaxGCPauseMillis=500
-XX:+UnlockExperimentalVMOptions
-XX:+AggressiveOpts
-XX:+DoEscapeAnalysis
-XX:+UseCompressedOops
-XX:InitiatingHeapOccupancyPercent=60
-XX:+UseG1GC
-XX:+PrintGCDateStamps
-XX:HeapDumpPath=JavaLogs\uat
-XX:+HeapDumpOnOutOfMemoryError
-Xloggc:jvm.log
-XX:+PrintGC

2014-05-14T08:22:11.173-0400: 495.992: [GC pause (partial) 1177M->1176M(2000M), 0.0178429 secs]
2014-05-14T08:22:11.188-0400: 496.011: [GC pause (partial) 1177M->1176M(2000M), 0.0085317 secs]
2014-05-14T08:22:11.188-0400: 496.021: [GC pause (partial) 1177M->1176M(2000M), 0.0022702 secs]
2014-05-14T08:22:11.204-0400: 496.025: [GC pause (partial) 1177M->1176M(2000M), 0.0028976 secs]
2014-05-14T08:22:11.204-0400: 496.029: [GC pause (partial) 1177M->1176M(2000M), 0.0021763 secs]
2014-05-14T08:22:11.204-0400: 496.032: [GC pause (partial) 1177M->1176M(2000M), 0.0020172 secs]
2014-05-14T08:22:11.204-0400: 496.035: [GC pause (partial) 1177M->1176M(2000M), 0.0020475 secs]
2014-05-14T08:22:11.219-0400: 496.039: [GC pause (partial) 1177M->1176M(2000M), 0.0022187 secs]
2014-05-14T08:22:11.219-0400: 496.042: [GC pause (partial) 1177M->1176M(2000M), 0.0020149 secs]
2014-05-14T08:22:11.219-0400: 496.045: [GC pause (partial) 1177M->1176M(2000M), 0.0021635 secs]
2014-05-14T08:22:11.219-0400: 496.049: [GC pause (partial) 1177M->1176M(2000M), 0.0019517 secs]
2014-05-14T08:22:11.219-0400: 496.052: [GC pause (partial) 1177M->1176M(2000M), 0.0022797 secs]
2014-05-14T08:22:11.235-0400: 496.055: [GC pause (partial) 1177M->1176M(2000M), 0.0020060 secs]
2014-05-14T08:22:11.235-0400: 496.058: [GC pause (partial) 1177M->1176M(2000M), 0.0019567 secs]
2014-05-14T08:22:11.235-0400: 496.062: [GC pause (partial) 1177M->1176M(2000M), 0.0019677 secs]
2014-05-14T08:22:11.235-0400: 496.065: [GC pause (partial) 1177M->1176M(2000M), 0.0019333 secs]
2014-05-14T08:22:11.251-0400: 496.068: [GC pause (partial) 1177M->1176M(2000M), 0.0021960 secs]
2014-05-14T08:22:11.251-0400: 496.071: [GC pause (partial) 1177M->1176M(2000M), 0.0020410 secs]
2014-05-14T08:22:11.251-0400: 496.075: [GC pause (partial) 1177M->1176M(2000M), 0.0019669 secs]
2014-05-14T08:22:11.251-0400: 496.078: [GC pause (partial) 1177M->1176M(2000M), 0.0018926 secs]
2014-05-14T08:22:11.251-0400: 496.081: [GC pause (partial) 1177M->1176M(2000M), 0.0019296 secs]
2014-05-14T08:22:11.266-0400: 496.084: [GC pause (partial) 1177M->1176M(2000M), 0.0025533 secs]
2014-05-14T08:22:11.266-0400: 496.088: [GC pause (partial) 1177M->1176M(2000M), 0.0022381 secs]
2014-05-14T08:22:11.266-0400: 496.091: [GC pause (partial) 1177M->1177M(2000M), 0.0020359 secs]
2014-05-14T08:22:11.266-0400: 496.094: [GC pause (partial) 1178M->1177M(2000M), 0.0018670 secs]
2014-05-14T08:22:11.266-0400: 496.097: [GC pause (partial) 1178M->1177M(2000M), 0.0021041 secs]
2014-05-14T08:22:11.282-0400: 496.101: [GC pause (partial) 1178M->1177M(2000M), 0.0022645 secs]
2014-05-14T08:22:11.282-0400: 496.104: [GC pause (partial) 1178M->1177M(2000M), 0.0020740 secs]
2014-05-14T08:22:11.282-0400: 496.107: [GC pause (partial) 1178M->1177M(2000M), 0.0020746 secs]
2014-05-14T08:22:11.282-0400: 496.110: [GC pause (partial) 1178M->1177M(2000M), 0.0019408 secs]
2014-05-14T08:22:11.282-0400: 496.113: [GC pause (partial) 1178M->1177M(2000M), 0.0021309 secs]
2014-05-14T08:22:11.297-0400: 496.117: [GC pause (partial) 1178M->1177M(2000M), 0.0020609 secs]
2014-05-14T08:22:11.297-0400: 496.120: [GC pause (partial) 1178M->1177M(2000M), 0.0019799 secs]
2014-05-14T08:22:11.297-0400: 496.123: [GC pause (partial) 1178M->1177M(2000M), 0.0019292 secs]
2014-05-14T08:22:11.297-0400: 496.126: [GC pause (partial) 1178M->1177M(2000M), 0.0019674 secs]
2014-05-14T08:22:11.297-0400: 496.129: [GC pause (partial) 1178M->1177M(2000M), 0.0021726 secs]
2014-05-14T08:22:11.313-0400: 496.133: [GC pause (partial) 1178M->1177M(2000M), 0.0021274 secs]
2014-05-14T08:22:11.313-0400: 496.136: [GC pause (partial) 1178M->1177M(2000M), 0.0019959 secs]
2014-05-14T08:22:11.313-0400: 496.139: [GC pause (partial) 1178M->1177M(2000M), 0.0019370 secs]
2014-05-14T08:22:11.313-0400: 496.142: [GC pause (partial) 1178M->1177M(2000M), 0.0019042 secs]
2014-05-14T08:22:11.313-0400: 496.145: [GC pause (partial) 1178M->1177M(2000M), 0.0021778 secs]
2014-05-14T08:22:11.329-0400: 496.149: [GC pause (partial) 1178M->1177M(2000M), 0.0020659 secs]
2014-05-14T08:22:11.329-0400: 496.152: [GC pause (partial) 1178M->1177M(2000M), 0.0019820 secs]
2014-05-14T08:22:11.329-0400: 496.155: [GC pause (partial) 1178M->1177M(2000M), 0.0019167 secs]

Answer 1

这绝对不是“正常”的行为。

但是，看起来这正是您选择的 GC 选项规定的内容：

• 堆大小为 2000Mb。（我不知道这是否是默认大小，或者您是否已指定它。）对于似乎具有~1200Mb 的工作集¹的应用程序来说，2000Mb 太小了……这个时间点。

• 您已经告诉 JVM 在堆达到 60% 时触发垃圾收集。2000Mb 的 60% 是 ~1200Mb (!)。

那么解决方案是什么？

• 最好的解决方案是增加堆大小。如果您保持其他 JVM 参数相同，并且程序工作集保持相同，那么我建议最小堆大小为 5Gb；即工作集大小的 3 倍 + 40%。

• 如果您准备好触发 60% 的占用率触发器，则可以使用更小的（小于 5Gb）堆运行……但会增加暂停时间较长的风险。

• 如果将“3 倍大小”压缩到 2 倍或更少，则增加了 GC 运行的频率，相应地增加了 GC 开销。（随着 GC 触发点接近程序的工作集大小，GC 开销会逐渐增加。）

• 如果您准备使用吞吐量收集器而不是低暂停收集器，那么您的 GC 开销很可能会减少。吞吐量收集器仅在“空间”实际填满时触发。当然，缺点是 GC 暂停。

如果堆大小和暂停时间要求是一成不变的，那么您唯一可行的选择是尝试减小程序的工作集大小。如果您的程序正在泄漏内存，请修复泄漏。否则，寻找会降低内存利用率的数据结构更改。

---

^{1 - 在此上下文中，工作集是在 GC 运行时发现可访问的对象集。}

Answer 2

这不正常。您可能创建了太多对象，而 GC 试图找到一些可用空间。但如果没有任何其他线索，我们无法帮助您。尝试一些分析——例如 jVisualVM、打开采样器、内存并观察对象实例的数量。如果没有内存泄漏，您可以尝试增加应用程序可用的内存。

Answer 3

GC 似乎每次调用只能回收 1 MB ( 1177M->1176M)。这显然是浪费时间，你需要给你的进程更多的内存。然后你会看到类似的东西2177M->1176M，GC 的频率将减少 1000 倍。