高 GC、CPU 活动和元空间似乎没有增加，Web 应用程序执行变得无响应

Question

我们正在对我们的项目进行性能测试和调整活动。我使用了 article

中提到的 JVM 配置

确切的 JVM 选项是：

  set "JAVA_OPTS=-Xms1024m -Xmx1024m 
                 -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=1024m 
                 -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled 
                 -XX:+UseCMSInitiatingOccupancyOnly 
                 -XX:CMSInitiatingOccupancyFraction=50 
                 -XX:+PrintGCDetails -verbose:gc  -XX:+PrintGCDateStamps 
                 -XX:+PrintGCApplicationStoppedTime 
                 -XX:+PrintGCApplicationConcurrentTime 
                 -XX:+PrintHeapAtGC -Xloggc:C:\logs\garbage_collection.logs 
                 -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 
                 -XX:GCLogFileSize=100m -XX:+HeapDumpOnOutOfMemoryError 
                 -XX:HeapDumpPath=C:\logs\heap_dumps\'date'.hprof 
                 -XX:+UnlockDiagnosticVMOptions"

我们仍然看到问题没有解决。我确信我们的代码（线程实现等）和我们使用的外部库（如 log4j 等）中存在一些问题，但我至少希望通过使用这些 JVM 调整选项来提高性能。

Gceasy.io 的报告表明：

您的应用程序似乎由于缺乏计算正在等待 资源 （CPU 或 I/O 周期）。严肃的生产应用程序不应该 由于计算资源而搁浅。在 1 个 GC 事件中，花费了“实时”时间 超过 'usr' + 'sys' 时间。

一些已知的代码问题：

1. 一些外部 web 应用程序有大量网络流量，它只接受一个 一次连接。 但我们的申请可以接受这种延迟。
2. Lo​​g4j 上的一些线程阻塞。我们使用 Log4j 进行控制台、数据库和文件附加。
3. MySQL 调优也可能存在问题。但就目前而言，我们想排除这些可能性，只了解可能影响我们执行的任何其他因素。

我希望通过调整，应该有更少的 GC 活动，应该正确管理元空间。但这不是观察到的，为什么？

以下是一些快照：

1. 在这里，我们可以了解元空间如何停留在 40MB 并且不超过该值。 还看到了很多 GC 活动

1. 另一个描述整个系统状态的图像：

我们的问题可能是什么？需要一些明确的指示！

UPDATE-1：磁盘使用监控

UPDATE-2：添加了带有堆的屏幕截图。

更多更新：好吧，我之前没有提到我们的处理涉及 selenium（测试自动化）执行，它使用 chrome/firefox webdrivers。在监控时，我看到在后台进程中，Chrome 正在使用大量内存。这可能是减速的可能原因吗？

以下是相同的屏幕截图：

其他显示后台进程的图片

EDIT No-5：添加 GC 日志

GC_LOGS_1

GC_LOGS_2

提前致谢！

Answer 1

您似乎没有 GC 问题。以下是您的应用运行 40 多个小时期间的 GC 暂停时间图：

从这张图我们可以看到大部分的GC停顿时间都在0.1秒以下，也有一部分在0.2-0.4秒之间，但是由于图本身包含了228000个数据点，所以很难弄清楚数据是怎么来的是分布式的。我们需要一个包含 GC 暂停时间分布的直方图。由于这些 GC 暂停时间中的绝大多数都非常低，只有很少的异常值，因此在直方图中线性绘制分布并不能提供信息。所以我创建了一个包含这些 GC 暂停时间的对数分布的图：

在上图中，X 轴是 GC 暂停时间的以 10 为底的对数，Y 轴是发生次数。直方图有 500 个 bin。

从这两张图中可以看出，GC 暂停时间分为两组，大部分 GC 暂停时间都非常低，在毫秒或更短的数量级上。如果我们也在 y 轴的对数刻度上绘制相同的直方图，我们会得到这个图： 在上图中，X 轴是 GC 暂停时间的 10 基对数，Y 轴是发生次数的 10 基对数。直方图有 50 个 bin。

在这张图上可以看到，我们有几十个 GC 暂停时间，这对于人类来说可能是可测量的，其数量级为十分之一秒。这些可能是您在第一个日志文件中的 120 次完整 GC。如果您使用具有更多内存并禁用交换文件的计算机，您可能可以进一步减少这些时间，以便所有 JVM 堆都保留在 RAM 中。交换，尤其是在非 SSD 驱动器上，可能是垃圾收集器的真正杀手。

---

我为您发布的第二个日志文件创建了相同的图表，这是一个小得多的文件，跨越大约 8 分钟的时间，包含大约 11000 个数据点，我得到了这些图像： 在上图中，X 轴是 GC 暂停时间的以 10 为底的对数，Y 轴是发生次数。直方图有 500 个 bin。 在上图中，X 轴是 GC 暂停时间的 10 基对数，Y 轴是发生次数的 10 基对数。直方图有 50 个 bin。

在这种情况下，由于您一直在不同的计算机上运行应用程序并使用不同的 GC 设置，因此 GC 暂停时间的分布与第一个日志文件不同。它们中的大多数都在亚毫秒范围内，有几十甚至几百在百分之一秒范围内。我们这里还有一些异常值在 1-2 秒范围内。有 8 次这样的 GC 暂停，它们都对应于发生的 8 次 full GC。

两个日志之间的差异以及第一个日志文件中缺少高 GC 暂停时间可能是由于运行生成第一个日志文件的应用程序的机器的 RAM 是第二个的两倍（8GB vs 4GB) 并且 JVM 也被配置为运行并行收集器。如果您的目标是低延迟，那么第一个 JVM 配置可能会更好，因为似乎完整的 GC 时间始终低于第二个配置。

很难说出您的应用存在什么问题，但似乎与 GC 无关。

Answer 2

我要检查的第一件事是磁盘 IO...如果您的处理器在性能测试期间没有 100% 加载，很可能磁盘 IO 是一个问题（例如您正在使用硬盘驱动器）...只需切换到 SSD（或在-内存盘）来解决这个问题

GC 只是做它的工作...你被选择concurrent collector 来执行 GC。

来自documentation：

大部分并发收集器同时执行其大部分工作（例如，在应用程序仍在运行时）以保持垃圾收集暂停时间较短。它专为具有中型到大型数据集的应用程序而设计，在这些应用程序中，响应时间比整体吞吐量更重要，因为用于最小化暂停的技术会降低应用程序性能。

你看到的符合这个描述：GC需要时间，但“主要”不会长时间暂停应用

---

作为一个选项，您可以尝试启用Garbage-First Garbage Collector（使用-XX:+UseG1GC）并比较结果。来自文档：

G1 计划作为 Concurrent Mark-Sweep Collector (CMS) 的长期替代品。将 G1 与 CMS 进行比较揭示了使 G1 成为更好解决方案的差异。一个区别是 G1 是一个压缩收集器。此外，与 CMS 收集器相比，G1 提供了更多可预测的垃圾收集暂停，并允许用户指定所需的暂停目标。

此收集器允许设置最大 GC 阶段长度，例如添加 -XX:MaxGCPauseMillis=200 选项，表示在 GC 阶段所需时间少于 200 毫秒之前您都可以。

Answer 3

检查您的日志文件。我最近在生产中看到了类似的问题，猜猜是什么问题。记录仪。 我们使用 log4j 非 asysnc 但这不是 log4j 问题。一些异常或情况导致在 3 分钟内记录了大约一百万行日志文件。再加上系统中的高容量和其他活动，导致高磁盘 I/O 和 Web 应用程序变得无响应。