Java挂了几秒，但是在gc log中没有发现gc pause

Question

我有一个使用 g1 gc 在 Linux (CentOS 7) 上运行的 java 应用程序，它经常挂起几秒钟，看起来就像 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 以及应用程序线程停止的总时间):

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进程还有一些运行native代码的线程，它们是用C写的，不受jvm的影响。这些线程运行良好，我很确定这是因为其中一个线程是心跳线程并且心跳超时为 800MS，但在暂停期间没有发现心跳超时。

我也监控了cpu的使用率，12核的cpu空闲率高达80%。

内存使用率也不是太高，THP(透明大页面)和交换内存也被禁用。

我发现了一件事我无法理解:

在停顿附近总会有一个concurrent-mark-start，无论哪里出现concurrent-mark-start，也会有一个停顿。

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秒才到达安全点，而自旋和出 block 时间都为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