为什么“PrintThreads”vm op 会导致应用程序中的长时间 vm 暂停？答案

【问题标题】：Why is "PrintThreads" vm op causing long vm pauses in the application?为什么“PrintThreads”vm op 会导致应用程序中的长时间 vm 暂停？
【发布时间】：2015-04-09 10:51:11
【问题描述】：

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

vm 暂停比 gc 暂停大得多，占总数的 90%。
虽然大多数暂停都是低延迟的，但我发现有几个 vm 暂停会在很长一段时间内停止我的应用程序。

在使用 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 中对应的 Safepoint 统计信息（相关部分）：

         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 引起的。

提前致谢。

【问题讨论】：

可以添加安全点统计输出吗？
PrintThreads 应该只是打印堆栈跟踪。它应该很快，4.5 秒没有意义。你有多少线程？它输出到哪里？如果它输出到一个缓慢的位置，可能需要一段时间来刷新输出？
@the8472 我已添加安全点统计信息。
@Pace 此应用程序中的线程数约为 90。当我进行负载测试时，线程数猛增到 190-200 左右。我不确定堆栈跟踪（如果有的话）指向哪里。您能否告诉我更多有关 PrintThreads vmop 的信息，例如何时或为何触发它？该应用程序确实维护了一个日志文件，其中维护了所有用户生成的日志。在大约 40 分钟的重负载测试期间，它会变得非常大（~650 MB）。这与“PrintThreads”vmop 有关吗？

标签： java performance jvm jvm-arguments jvm-hotspot

【解决方案1】：

您能否告诉我更多关于 PrintThreads vmop 的信息，例如何时或为何触发它？

有几种触发方式

向进程发送 SIGBREAK / 在控制台中按 Ctrl+Break。
从本机代码调用JVM_DumpAllStacks
附加执行线程转储的 java 代理（分析器/监控工具）
通过DiagnosticCommandMBean调用

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

【讨论】：