JVM GC 工作方式很奇怪

Question

在尝试了多种不同的 JVM GC 设置并进行了大量测试后，我遇到了长时间主要 GC 暂停的问题，现在我正在使用 G1GC JVM GC 进行测试。除此之外，我还使用性能监视器收集数据，并且只有正在运行的应用程序（除了系统服务，...）是包含我的应用程序的 GlassFish 服务器。我在性能监视器日志中没有发现任何奇怪的东西（CPU 使用率约为 5-10%，当 GC 发生时，它会变得更高一点，内存使用率约为 60%，...）。现在是测试的第五天，我注意到以下内容：

直到第二次主要（混合）GC 发生时，一切都很好（次要 GC 大约 20 毫秒长，GC 性能为 160000M/s，...）。第二次主要 GC 花费了大约 2 秒（长 - 第一次花费了 150 毫秒，但并不重要），之后次要 GC 比之前长得多（参见图中的灰线，代表次要（年轻）GC 的持续时间）和 GC 性能只有12000M/s并且还在下降。我想知道为什么在第二次主要 GC 之后会发生这种情况，即使没有其他应用程序正在运行并且 CPU/内存使用情况与以前相同。我不知道这里发生了什么。我还有一个问题 - 我在不同的 PC 上运行相同的测试，这些 PC 的 RAM 较少，处理器较旧，GC 性能约为 5000M/s（次要 GC 约为 50-100ms），我认为这是正常的，因为处理器较差和更少的内存。奇怪的是，运行 3 天后，Major GC 还没有发生，而且即使设置相同，老年代的增长也比这里慢得多。为什么增长速度慢得多（这里两天大约 150MB，第二台 PC 三天 80MB）？感谢您的所有回答，我不知道为什么 GC 表现如此异常（首先它工作正常，然后性能恶化）。

编辑：这是在 GCViewer 中导入的完整 GC 日志文件以及来自 GCViewer 的事件详细信息统计信息：

第三次主要 GC 的日志：

2015-06-08T08:09:13.123+0200: 572815.533: [GC concurrent-root-region-scan-start]
2015-06-08T08:09:13.139+0200: 572815.560: [GC concurrent-root-region-scan-end, 0.0271771 secs]
2015-06-08T08:09:13.139+0200: 572815.560: [GC concurrent-mark-start]
2015-06-08T08:09:16.302+0200: 572818.721: [GC concurrent-mark-end, 3.1612900 secs]
2015-06-08T08:09:16.318+0200: 572818.729: [GC remark 572818.729: [Finalize Marking, 0.0002590 secs] 572818.729: [GC ref-proc, 0.4479462 secs] 572819.177: [Unloading, 3.2004912 secs], 3.6499382 secs]
 [Times: user=0.20 sys=0.08, real=3.64 secs] 

再次强调，实时性远高于user + sys，Unloading阶段花费了3秒多。

Answer 1

如果不深入研究问题，无法给您经过验证的解释，但让我们尝试一下。

您很可能阅读过 G1 GC oracle 文档，并知道该收集器是为具有巨大堆的应用程序而设计的。它旨在减少主要垃圾收集期间的长时间停顿。

在您的示例中，我们可以看到次要 GC 暂停在第二次主要 GC 之后立即增加。我不知道G1的内部机制，但直觉告诉我，第二次主要GC是G1分析其性能的内部“信号”（他是否实现了吞吐量目标/暂停目标）。所以在我看来，经过这次分析，G1决定改变它的内部参数。我敢打赌，较长的次要 GC 暂停表明 G1 增加了年轻代空间。

他为什么这么做？嗯，更大的年轻一代会降低向老一代的晋升速度。所以老年代空间被填满的速度会比较慢。最有可能的是，G1 试图阻止下一次主要 GC 暂停时间与上一次一样长（2 秒）。

再说一遍，如果没有深入分析，我不能保证事情会像我说的那样进行，但我会尽力为您提供指导。

那你的“较慢”机器呢？它运行了 3 天，没有发生重大 GC 暂停 - 如果不知道 GC 配置和应用程序如何工作，真的很难说。我敢打赌应用程序负载会更低。