java - 为什么 "PrintThreads"vm op 会导致应用程序中的长时间 vm 暂停？

Question

我正在使用 -XX:+PrintSafepointStatistics、-XX:+PrintGCApplicationStoppedTime 和 -XX:+PrintGCApplicationConcurrentTime 等运行 jvm 以调查 gc 暂停。我注意到了

1. vm 暂停次数远大于 gc 暂停次数，占总数的 90%。

2. 虽然大多数暂停都是低延迟的，但我发现一些虚拟机暂停使我的应用程序停止了很长时间。

在使用 PrintSafepointStatistics 标志进行进一步调查时(如本博客中的建议:http://jpbempel.blogspot.in/2013/03/safety-first-safepoints.html)，我发现一个特定的 vm-op“PrintThreads”导致长达 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:+PrintGCDetails -XX:+PrintGCTimeStamps - XX:+PrintTenuringDistribution -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -XX:MaxNewSize=1638m -XX:NewSize=1638m -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1"

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.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 中的“PrintThreads”vmop。我已经在多个实例中验证了这一观察。超过 1 秒的暂停总是由“PrintThreads”vmop 引起。

提前致谢。

Answer 1

Could you tell me anything more about the PrintThreads vmop like when or why is it triggered?

有多种触发方式

• 向进程发送 SIGBREAK/在控制台中按 Ctrl+Break。
• 从 native 代码调用 JVM_DumpAllStacks
• 附加执行线程转储的 Java 代理(分析器/监视工具)
• 通过DiagnosticCommandMBean调用

只是推测，但如果触发 vmop 的任何内容都通过网络连接写入，而另一端的任何内容都很慢，那么可能会导致整个虚拟机停顿。