java - 如何解读Java G1 GC暂停时间原因

Question

在使用 G1 收集器时，我们一直在努力解决似乎长时间停止世界暂停的问题。我已经通读了 Oracle 文档，但我仍然无法确定如何解释导致长时间暂停的原因以及如何处理它。 (下方的 GC 日志)

我们的实例正在被监控，我有以下图表中包含的信息:

我们有另一个监视 JVM 的监视工具，我让它报告说 JVM 大约在同一时间没有响应 12 秒。

所以这让我想到了如何处理这个问题。服务器上的负载非常低，所以这种情况不会经常发生，但似乎在几个小时内堆不断增长，然后出现一个巨大的 GC 事件，可能会导致严重的问题。以下是我们用于 GC 的配置:

   wrapper.java.additional.40=-XX:+UseG1GC

   wrapper.java.additional.44=-XX:+ScavengeBeforeFullGC


   wrapper.java.additional.50=-XX:+PrintGCCause
   wrapper.java.additional.51=-XX:+PrintGCDetails
   wrapper.java.additional.52=-XX:+PrintGCTimeStamps
   wrapper.java.additional.53=-XX:+PrintGCApplicationStoppedTime
   wrapper.java.additional.54=-XX:+PrintGCApplicationConcurrentTime
   wrapper.java.additional.55=-verbose:gc
   wrapper.java.additional.56=-Xloggc:../../../logs/gc.log
   wrapper.java.additional.57-XX:+UseGCLogFileRotation
   wrapper.java.additional.58-XX:NumberOfGCLogFiles=10
   wrapper.java.additional.59-XX:GCLogFileSize=100M
   wrapper.java.additional.60=-XX:+PrintHeapAtGC
   wrapper.java.additional.61=-XX:+PrintTenuringDistribution
   wrapper.java.additional.62=-XX:+UseCompressedClassPointers
   wrapper.java.additional.63=-XX:+UseCompressedOops

任何人都可以在这里指出我正确的方向。谢谢!

GCEasy 分析:http://gceasy.io/my-gc-report.jsp?p=c2hhcmVkLzIwMTcvMDYvMjcvLS1nYyAoMSkubG9nLnppcC0tMTgtNDEtNDA=

更新:元空间图

更新:GC 日志:https://dl.dropboxusercontent.com/u/3642047/gc.log.zip

Answer 1

我在您的 GC 日志中看到至少两个问题:

1. System.gc() 或 Runtime.getRuntme().gc() 显式调用了 4 个完整集合。每个大约 10 秒长:

   277042.600: [Full GC (System.gc())  12G->1537M(5126M), 11.4203806 secs]
   

   您可能需要添加 -XX:+ExplicitGCInvokesConcurrent JVM 标志以防止 System.gc() 导致世界停止事件。

   查找谁调用了 System.gc() 并且可能完全避免此调用也很有用。为此，您可以通过添加代码来打印堆栈跟踪来修改 Runtime.gc 方法。然后重新编译 Runtime.java 并将修改后的类添加到引导类路径中
   -Xbootclasspath/p:/path/to/yourpatch.jar

2. 另一个问题是与 GC 无关的超长安全点同步暂停:

   5512447.686: Total time for which application threads were stopped: 16.4426008 seconds, Stopping threads took: 16.4414390 seconds
   

   这通常是由 MappedByteBuffer I/O 或 Java 进程开始交换到磁盘引起的。参见 this和 this类似问题的答案。