为什么“打印线程”vm op会导致应用程序中的长时间vm暂停？

Question

我正在使用-XX： PrintSafepoint统计、-XX： PrintGCApplication ationStopedTime和-XX： PrintGCApplication ationConrealtTime等运行jvm来调查gc暂停。我注意到

>

vm暂停比gc暂停大得多，占总数的90%。

虽然大多数暂停都是低延迟的，但我发现有几次vm暂停让我的应用程序停止了很长时间。

在使用PrintSafepoint统计标志的进一步调查中（如本博客所建议的：http://jpbempel.blogspot.in/2013/03/safety-first-safepoints.html），我发现一个特定的vm-op“打印线程”会导致长达4.5秒和1.3秒的暂停。

我想知道是什么触发了这个vmop，为什么它占用了这么多时间。如果它有帮助，以下是我正在使用的所有jvm标志的列表：

JAVA _ OPTS = " $ JAVA _ OPTS-XX:UseParallelOldGC "

CATALINA _ OPTS = "-Xms2G-Xmx4G-XX:MaxPermSize = 256m-Xloggc:/path/to/Tomcat/Apache-Tomcat-8 . 0 . 18/logs/GC . log-XX:printgc details-XX:printgcstimestamps-XX:printtenuingdistribution-XX:printgapplicationstoppedtime-XX:printgapplicationconcurrenttime-XX:MaxNewSize = 1638m-XX:NewSize = 1638m-XX:PrintSafepointStatistics-XX:printgsafepointstatistics-XX

应用程序停止时间输出（以 gc.log 为单位）（相关部分）：

1649.008: Application time: 0.0001730 seconds  
1649.009: Total time for which application threads were stopped: 0.0003760 seconds  
**1650.805**: Application time: 1.7963630 seconds  
1655.315: Total time for which application threads were stopped: **4.5099710 seconds**  
1655.315: Application time: 0.0000350 seconds  
1655.316: Total time for which application threads were stopped: 0.0005540 seconds  
1655.316: Application time: 0.0001600 seconds  

catalina中相应的Safepoint统计数据。out（相关部分）：

         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
1649.008: RevokeBias                       [     165          0              0    ]      [     0     0     0     0     0    ]  0   

         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
**1650.805**: PrintThreads                     [     168          0              0    ]      [     0     0     0     0  4509    ]  0   

         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
1655.315: PrintJNI                         [     168          0              0    ]      [     0     0     0     0     0    ]  0   

应用程序线程停止4.5秒之前的最后时间戳是1650.805。此时间戳对应于catalina.out.中的“PrintThreadsvmop”，我已经在多个实例中验证了这一观察结果。大于1秒的暂停总是由“PrintThreadsvmop”引起的。

提前致谢。

Answer 1

你能告诉我更多关于PrintThreads vmop的信息吗，比如它是什么时候或者为什么被触发的？

有几种方法可以触发它

• 将SIGBREAK发送到进程/在控制台中点击Ctrl-Break
• 从本机代码调用JVM_DumpAllStacks
• 连接执行线程转储的java代理（探查器/监视工具）
• 通过DiagnosticCommandMBean调用

只是猜测，但是如果任何触发vmop的东西都是通过网络连接写入的，而另一端的任何东西都很慢，那么这可能会导致整个VM暂停。