JVM stop the world

zero__007

于 2024-01-09 23:00:00 发布

阅读量171

点赞数

CC 4.0 BY-SA版权

分类专栏： JVM 文章标签： jvm

原文链接：https://zhuanlan.zhihu.com/p/91937583

JVM 专栏收录该内容

35 篇文章

订阅专栏

转载自：https://zhuanlan.zhihu.com/p/91937583

文章目录

一、遇到的问题

Total time for which application threads were stop 超级长时间，这行日志代表什么，以及为什么时间会这么长 ?

二、日志的含义

当GC发生时，每个线程只有进入了SafePoint才算是真正挂起，也就是真正的停顿，这个日志的含义是整个GC过程中STW的时间，配置了 -XX:+PrintGCApplicationStoppedTime 这个参数才会打印这个信息。
重点： 第一个 2.81 seconds 是JVM启动后的秒数?，第二个 2.68 seconds 是 JVM发起STW的开始到结束的时间。特别地，如果是GC引发的STW，这条内容会紧挨着出现在GC log的下面。

日志统计脚本：

tail -f xxx.gc.log | grep 'application threads were stopped' | awk '$(NF-6)>0.05'

三、安全点是什么

从线程角度看，safepoint可以理解成是在代码执行过程中的一些特殊位置，当线程执行到这些位置的时候，说明虚拟机当前的状态是安全的，如果有需要，可以在这个位置暂停，比如发生GC时，需要暂停暂停所以活动线程，但是线程在这个时刻，还没有执行到一个安全点，所以该线程应该继续执行，到达下一个安全点的时候暂停，等待GC结束。

从线程的角度，安全点是代码执行中的一些特殊位置，当线程执行到这些特殊的位置，如果此时在GC，那么在这个地方线程会暂停，直到GC结束。
GC的时候要挂起所有活动的线程，因此线程挂起，会选择在到达安全点的时候挂起。
安全点这个特殊的位置保存了线程上下文的全部信息。说白了，在进入安全点的时候打印日志信息能看出线程此刻都在干嘛。

有关安全点的详细说明，请移步：
JVM源码分析之安全点safepoint

四、什么时候会STW？（换句话说什么时候会触发进入安全点？）

Garbage collection pauses（垃圾回收）
JIT相关，比如Code deoptimization, Flushing code cache
Class redefinition (e.g. javaagent，AOP代码植入的产生的instrumentation)
Biased lock revocation 取消偏向锁
Various debug operation (e.g. thread dump or deadlock check) dump 线程

五、STW的说明

配置 -XX:+PrintSafepointStatistics –XX:PrintSafepointStatisticsCount=1 参数，虚拟机会打印如下日志文件:

vmop [threads: total initially_running wait_to_block]  [time: spin block sync cleanup vmop] page_trap_count  370337.312: GenCollectForAllocation     [  1070     2       3  ]   [ 8830   0 8831   1  24  ]

-XX:+PrintSafepointStatistics 打印安全点统计信息，
-XX:PrintSafepointStatisticsCount=n 设置打印安全点统计信息的次数；

5.1 日志分析

vmop： 引发STW的原因，以及触发时间。该项常见的输出有：RevokeBias、BulkRevokeBias、Deoptimize、G1IncCollectionPause。数字370337.312是虚拟机启动后运行的秒数。GC log可以根据该项内容定位Total time for which application threads…引发的详细信息。
total ： STW发生时，JVM存在的线程数目，这里的值是1070。
initially_running ： STW发生时，仍在运行的线程数，这里的值是2。这项是Spin阶段的时间来源。
wait_to_block ： STW需要阻塞的线程数目，这里的值是3。这项是block阶段的时间来源
sync = spin + block + 其他。

5.2 由日志可以看出，safepoint的执行分为四个阶段

Spin阶段。因为jvm在决定进入全局safepoint的时候，有的线程在安全点上，而有的线程不在安全点上，这个阶段是等待未在安全点上的用户线程进入安全点。
Block阶段。即使进入safepoint，用户线程这时候仍然是running状态，保证用户不在继续执行，需要将用户线程阻塞。
Cleanup。这个阶段是JVM做的一些内部的清理工作。
VM Operation. JVM 执行的一些全局性工作，例如 GC, 代码反优化。

5.3 vmop 输出说明

RevokeBias、BulkRevokeBias、偏向锁取消情况。
Deoptimize、
G1IncCollectionPause GC GC 执行情况。

5.4 优化说明

分析 -XX:+PrintSafepointStatistics –XX:PrintSafepointStatisticsCount=1 产生的日志信息基本上STW的原因都是RevokeBias或者BulkRevokeBias。

这个是撤销偏向锁操作，虽然每次暂停的时间很短，但是特别频繁出现也会很耗时。
一些高并发的系统中，禁掉JVM偏向锁优化，可以提升系统的吞吐量。

禁用偏向锁的参数为: -XX:-UseBiasedLocking

还有一种常见会有长时间STW：

当发生GC时，有线程迟迟进入不到safepoint进行阻塞，导致其他已经停止的线程也一直等待，VM Thread也在等待所有的Java线程挂起才能开始GC，这里需要分析业务代码中是否存在有界的大循环逻辑，可能在JIT优化时，这些循环操作没有插入safepoint检查。

https://xie.infoq.cn/article/60db3144cb07afba7060bd36f
https://zhuanlan.zhihu.com/p/91937583
https://blog.csdn.net/iter_zc/article/details/41892567