如何让 G1 打印更多日志详细信息？答案

【问题标题】：How do I get G1 to print more log details?如何让 G1 打印更多日志详细信息？
【发布时间】：2016-02-25 05:01:46
【问题描述】：

我正在测试基于 Jetty 的 API 与基于 Netty 的 API。实验中唯一的区别是我使用的 API（相同的应用程序、相同的服务器、相同的内存配置、相同的负载等），我使用基于 Netty 的 API 获得了更长的 GC 暂停。大多数情况下，停顿低于一毫秒，但在平稳运行几天后，每 12-24 小时我会看到 4-6 秒的停顿，而基于 Jetty 的 API 不会出现这种停顿。

无论何时发生这种情况，关于 G1 正在做什么导致它发出 STW 的信息都非常少，请注意此处的第二条暂停消息：

2016-02-23T05:22:27.709+0000: 66360.282: Total time for which application threads were stopped: 0.0319639 seconds, Stopping threads took: 0.0000716 seconds
2016-02-23T05:22:35.642+0000: 66368.215: Total time for which application threads were stopped: 6.9705594 seconds, Stopping threads took: 0.0000737 seconds
2016-02-23T05:22:35.673+0000: 66368.246: Total time for which application threads were stopped: 0.0048374 seconds, Stopping threads took: 0.0040574 seconds

我的 GC 选项是：

-XX:+UseG1GC 
-XX:+G1SummarizeConcMark 
-XX:+G1SummarizeRSetStats 
-XX:+PrintAdaptiveSizePolicy 
-XX:+PrintGC 
-XX:+PrintGCApplicationStoppedTime 
-XX:+PrintGCDateStamps 
-XX:+PrintGCDetails 
-XX:+PrintGCTimeStamps 
-XX:+DisableExplicitGC 
-XX:InitialHeapSize=12884901888 
-XX:MaxHeapSize=12884901888

并且，作为参考，我的虚拟机选项是：

-XX:+AlwaysPreTouch 
-XX:+DebugNonSafepoints 
-XX:+FlightRecorder 
-XX:FlightRecorderOptions=stackdepth=500 
-XX:-OmitStackTraceInFastThrow 
-XX:+TrustFinalNonStaticFields 
-XX:+UnlockCommercialFeatures 
-XX:+UnlockDiagnosticVMOptions 
-XX:+UnlockExperimentalVMOptions 
-XX:+UseCompressedClassPointers 
-XX:+UseCompressedOops

我如何找出为什么 G1 在2016-02-23T05:22:35.642 停止了世界？

【问题讨论】：

您应该会看到使用这些设置的大量（我的意思是很多）输出。您确定您正在寻找正确的位置吗？
我的意思是，有大量的输出，除了less 之外的任何文件都无法打开 :) 但绝大多数是这些“线程已停止”行，以及暂停> 从不仅仅是“线程已停止”的任何日志消息中删除的暂停时间本身比暂停时间多几毫秒。

标签： java garbage-collection g1gc

【解决方案1】：

并非所有 STW 暂停 - 用于触发它们的机制称为 safepoint - 是由 GC 引起的，请使用 -XX:+PrintSafepointStatistics –XX:PrintSafepointStatisticsCount=1 打印其他安全点原因。

其次，如果暂停是由 GC 引起的，那么您自己粘贴的行不包含原因，但 GC 日志中的相邻块应该包含原因，例如 [GC pause (G1 Evacuation Pause) (young), 0.0200285 secs]

此外，您可能还想监控磁盘 IO 延迟并将时间戳与安全点暂停相匹配。在安全点期间发生的任何同步 IO 或分页都会导致存储速度变慢，可能会停止整个安全点。将日志文件和/tmp 放在 tmpfs 或 SSD 上可能会有所帮助。

【讨论】：

上面的消息确实在几秒钟前之前是这样的：gist.github.com/jakewins/6d5f671a2fc400c95bfe - 但我找不到关于如何判断这是否与 2 秒后发生的暂停有关的文档/信息它打印 GC 信息

【解决方案2】：

为此添加一些关闭：问题在于，从技术上讲，这不是 GC 暂停；这是几个因素的组合：

AWS 将 IO 限制为您支付的费用
/tmp 在 Ubuntu 上默认结束在我们的（受限制的）EBS 卷上
JVM 在 stop-the-world(!) 期间默认写入 /tmp

我们应用程序的其他部分达到了 EBS 限制阈值，当 JVM 在 STW 期间尝试写入 /tmp 时，JVM 上的所有线程都在 AWS 限制点后面排队。

Netty/Jetty 的区别似乎是一个红鲱鱼。

我们需要我们的应用程序能够在这种环境中生存，因此我们的解决方案是禁用这种 JVM 行为，代价是失去了我们添加的几个 JVM 工具的支持：

-XX:+PerfDisableSharedMem

关于这个问题的更多信息来自这篇优秀的博文：http://www.evanjones.ca/jvm-mmap-pause.html

【讨论】：