JVM垃圾回收工作非常奇怪

Question

JVM垃圾回收工作非常奇怪

5

在我尝试了许多不同的JVM GC设置并进行了大量测试后，我现在正在测试G1GC JVM GC。除此之外，我还使用性能监视器收集数据，并且唯一运行的应用程序（除系统服务之外）是GlassFish服务器和我的应用程序。我在性能监视器日志中没有发现任何奇怪的情况（CPU使用率约为5-10％，当GC发生时会略微增加，内存使用率约为60％ ...）。现在是第五天的测试，我注意到以下情况：

enter image description here

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

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

enter image description here

第三个主要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]

再次提醒，实时响应时间远高于用户+系统时间，卸载阶段需要超过3秒的时间。

- user4341206

请描述颜色代表什么，这些增长线代表什么。我们能在这里看到主要GC的持续时间吗？如果可以，它们在哪里？ - AdamSkywalker

你能提供感兴趣时间段内的原始GC日志吗？同时确保使用-XX:+PrintGCDetails进行记录。 - the8472

我尝试使用Pastebin分享它，但无法粘贴所有日志代码（5MB大小）... - user4341206

我使用性能监视器监控了系统，但没有发现可能存在资源问题。是什么导致应用程序达到安全点，我该如何找出是否存在问题？ - user4341206

@user4341206 进展如何了？ - AdamSkywalker

显示剩余5条评论

2个回答

1

如果不深入研究问题，我无法给您提供验证过的解释，但我们可以尝试。

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

在您的示例中，我们可以看到次要GC暂停在第二个主要GC之后增加。我不知道G1的内部机制，但直觉告诉我，第二个主要GC是G1进行性能分析（是否实现吞吐量目标/暂停目标）的内部“信号”。因此，我认为，在此分析之后，G1决定更改其内部参数。我敢打赌，长时间的次要GC暂停表明G1增加了年轻代空间。

为什么会这样？好吧，更大的年轻代将减慢晋升速度到老年代。因此，老年代空间将填充得更慢。最有可能的是，G1试图防止下一个主要GC暂停与上一个（2秒钟）一样长。

同样，如果不进行深入分析，我不能保证事情像我说的那样运作，但我会尽力给您指引。

那么，对于您的“较慢”机器，在没有主要GC暂停的情况下工作了3天 - 如果不知道GC配置和应用程序的工作方式，很难说。

- AdamSkywalker

但是如果GC真的这样决定，那么吞吐量和GC性能将会降低（现在GC性能大约降低了20％，吞吐量目前仅为0.02％）。我真的很想知道下一个主要GC需要多长时间。请问您是否建议我不要在我的服务器上使用G1GC，因为堆大小较小？如果是这样，请告诉我如何设置CMS以获得更短的暂停时间（请参见我在先前评论中发布的链接的其他问题？谢谢... - user4341206

1

正如@the8472所提到的，您可以通过指定标志为G1设置暂停目标。我在答案中没有提到这个，因为我认为您已经这样做了。无论如何，我阅读了您的第二个问题以获取更多细节。对于512 Mb堆而言，您有非常长的主要GC时间。这不是GC问题。我敢打赌问题在于 1）Glassfish服务器 2）Windows工具。我会尝试使用Tomcat或切换到Linux。我有一个真实的经验，当时Windows性能计数器极大地减缓了应用程序的速度。 - AdamSkywalker

祝你好运，我会偶尔查看这个话题，因为它很有趣。 - AdamSkywalker

@user4341206 看起来重新启动服务器是一个选项 :) 比之前的15秒好多了。让我们看看接下来会发生什么。 - AdamSkywalker

我们等着瞧。如果你知道答案，我还有一个问题要问你。如果我使用-XX：-ClassUnloadingWithConcurrentMark标志，在G1并发标记后关闭类卸载，那么类卸载将在哪个阶段执行（哪个阶段）？我已经搜索过了，但还没有找到答案。@the8472建议我使用此标志来减少重新标记阶段中的卸载时间（您可以看到这是上次GC重新标记阶段中最长的时间）。 - user4341206

显示剩余3条评论

网页内容由stack overflow 提供, 点击上面的

可以查看英文原文，
原文链接

- the8472 · Accepted Answer

由于您似乎关心暂停时间，我在您的JVM标志中没有看到任何暂停时间目标。

您可以通过MaxGCMinorPauseMillis（仅限minor）和MaxGCPauseMillis（总体）来设置暂停时间目标。

这些只是目标，收集器可能由于各种原因无法达到这些目标。默认情况下，GC只允许在GC上烧掉1％的CPU时间。因此，如果未能达到其目标，则可以尝试设置GCTimeRatio=19，以代价吞吐量换取暂停时间，从而将其时间增加至5％。

您日志中最长的暂停似乎是这个：

2015-06-05T09:14:51.909+0200: 317539.613: [GC remark 317539.613: [Finalize Marking, 0.0003625 secs] 317539.613: [GC ref-proc, 0.9890475 secs] 317540.602: [Unloading, 0.9739555 secs], 1.9643775 secs]

你可以尝试使用-XX:+ParallelRefProcEnabled来缩短引用处理时间。