java stop-the-world_(干货篇) JVM stop the world

一、遇到的问题

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

二、日志的含义Total time for which application threads were stopp 2.81 seconds，Stopping threads took ：2.6 seconds

当GC发生时，每个线程只有进入了SafePoint才算是真正挂起，也就是真正的停顿，这个日志的含义是整个GC过程中STW的时间，配置了 -XX:+PrintGCApplicationStoppedTime 这个参数才会打印这个信息。

重点： 第一个 2.81 seconds 是JVM启动后的秒数，第二个 2.6 seconds 是 JVM发起STW的开始到结束的时间。特别地，如果是GC引发的STW，这条内容会紧挨着出现在GC log的下面。

三、安全点是什么从线程的角度，安全点是代码执行中的一些特殊位置，当线程执行到这些特殊的位置，如果此时在GC，那么在这个地方线程会暂停，直到GC结束。

GC的时候要挂起所有活动的线程，因此线程挂起，会选择在到达安全点的时候挂起。

安全点这个特殊的位置保存了线程上下文的全部信息。说白了，在进入安全点的时候打印日志信息能看出线程此刻都在干嘛。

四、什么是STW(stop the world)

等待所有用户线程进入安全点后并阻塞，做一些全局性操作的行为。

五、什么时候会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 参数，虚拟机会打印如下日志文件:-XX:+PrintSafepointStatistics 打印安全点统计信息，

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

6.1 日志分析：vmop： 引发STW的原因，以及触发时间，本例中是GC。该项常见的输出有：RevokeBias、BulkRevokeBias、Deoptimize、G1IncCollectionPause。

数字306936.812是虚拟机启动后运行的秒数。GC log可以根据该项内容定位Total time for which application threads…引发的详细信息。

total ： STW发生时，JVM存在的线程数目。

initially_running ： STW发生时，仍在运行的线程数，这项是Spin阶段的 时间来源

wait_to_block ： STW需要阻塞的线程数目，这项是block阶段的时间来源

sync = spin + block + 其他。

6.2 由日志可以看出，safepoint的执行分为四个阶段：Spin阶段。因为jvm在决定进入全局safepoint的时候，有的线程在安全点上，而有的线程不在安全点上，这个阶段是等待未在安全点上的用户线程进入安全点。

Block阶段。即使进入safepoint，用户线程这时候仍然是running状态，保证用户不在继续执行，需要将用户线程阻塞。

Cleanup。这个阶段是JVM做的一些内部的清理工作。

VM Operation. JVM 执行的一些全局性工作，例如 GC, 代码反优化。

6.3 vmop 输出说明

RevokeBias、BulkRevokeBias、偏向锁取消情况。

Deoptimize、

G1IncCollectionPause GC GC 执行情况。

6.3 优化说明

分析 -XX:+PrintSafepointStatistics –XX:PrintSafepointStatisticsCount=1 产生的日志信息基本上STW的原因都是RevokeBias或者BulkRevokeBias。这个是撤销偏向锁操作，虽然每次暂停的 时间很短，但是特别频繁出现也会很耗时。

一些高并发的系统中，禁掉JVM偏向锁优化，可以提升系统的吞吐量。禁用偏向锁的参数为: -XX:-UseBiasedLocking

七、引起长时间STW原因GC

RevokeBias 撤销偏向锁操作也会消耗很长时间。在高并发系统中，建议禁用偏向锁。

百分之九十的情况都是以上2个原因。

八、现场

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

果然是撤销偏向锁搞得鬼，增加 -XX:-UseBiasedLocking 后，问题得到解决.

作者：丶Joy丶