Java 挂起几秒钟，但在 gc 日志中没有发现 gc 暂停

Question

我在 Linux (CentOS 7) 上有一个 java 应用程序运行使用 g1 gc，它经常挂起几秒钟，看起来就像 gc 暂停一样，但我在 gc 日志中找不到这么长的停顿。

为了确保 java 应用程序挂起，我启动了一个后台线程，该线程除了每 500 毫秒打印一次日志外什么都不做。并且发现日志暂停了几秒钟。这是日志，它暂停在 [14:31:02,834] 到 [14:31:05,677]

WARN [2018-07-16 14:30:57,831][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:30:58,331][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:30:58,832][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:30:59,332][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:30:59,832][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:00,333][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:00,833][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:01,333][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:01,834][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:02,334][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:02,834][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:05,677][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:06,177][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:06,678][clock]py.datanode.DataNodeAppEngine(196):tick...
WARN [2018-07-16 14:31:07,178][clock]py.datanode.DataNodeAppEngine(196):tick...

同时 gc 日志（grep with Total time for which application threads are stopped）：

2018-07-16T14:30:58.327+0800: 2679.423: Total time for which application threads were stopped: 0.3750533 seconds, Stopping threads took: 0.0003430 seconds
2018-07-16T14:31:05.176+0800: 2686.272: Total time for which application threads were stopped: 0.5037637 seconds, Stopping threads took: 0.0004556 seconds
2018-07-16T14:31:06.978+0800: 2688.074: Total time for which application threads were stopped: 0.0060367 seconds, Stopping threads took: 0.0003190 seconds

此外，这个java进程还有一些线程运行原生代码，它们是用C写的，不受jvm的影响。这些线程是运行嗯，我很确定这是因为其中一个线程是心跳线程并且心跳超时是800MS，但是在暂停期间没有发现心跳超时。

我也监测了cpu的使用情况，12核的cpu闲置率高达80%。

内存使用率也不算太高，THP（透明大页面）和交换内存也被禁用。

而且我发现了一件事我无法理解：

在停顿附近总会有一个并发标记开始，无论哪里出现并发标记开始，也会有一个停顿。

2018-07-16T14:30:58.489+0800: 2679.586: [GC concurrent-mark-start]

我知道并发标记阶段不会导致STW，但我不敢相信这只是巧合，因为我复制了很多次，它总是这样。

这是 YourKit 暂停期间的 CPU 使用情况和内存使用情况：

感谢@jspcal 的建议，我得到了 SafepointStatistics :

         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
2566.430: G1IncCollectionPause             [     745          0              0    ]      [     0     0  2705     3   474    ]  0

G1IncCollectionPause用了近3秒才到达安全点，而自旋和出块时间都为0

Answer 1

虽然 GC 是 VM 暂停的来源之一，但安全点（停止世界暂停）可以由其他操作启动，例如刷新代码缓存、偏向锁定、某些调试操作等。这里是 list of safepoint operations .要对这些安全点进行故障排除，请使用以下选项：

安全点：

-XX:+UnlockDiagnosticVMOptions
-XX:+PrintSafepointStatistics
-XX:PrintSafepointStatisticsCount=1
-XX:+SafepointTimeout
-XX:SafepointTimeoutDelay=500
-XX:+LogVMOutput
-XX:LogFile=/var/log/jvm/vm.log

GC:

-verbose:gc
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCApplicationConcurrentTime
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails 
-Xloggc:/var/log/jvm/garbage.log
-XX:+UseGCLogFileRotation
-XX:NumberOfGCLogFiles=10
-XX:GCLogFileSize=100M

Answer 2

最后我发现它是由 jdk 关于大型引用数组的并发标记的错误引起的：

Large reference arrays cause extremely long synchronization times

我的解决方案是将大参考数组更改为分块二维数组

Java 挂起几秒钟，但在 gc 日志中没有发现 gc 暂停

Java hangs for several seconds, but no gc pause found in gc log

java

linux

garbage-collection

g1gc