(干货篇) JVM stop the world

1、遇到的问题

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

2、日志的含义

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的下面。

3、安全点是什么

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

有关安全点的详细说明，请移步：

JVM源码分析之安全点safepoint

[Java JVM] Hotspot GC研究- GC安全点 (Safepoint&Stop The World)

4、什么是STW(stop the world)

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

5、何时会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 线程

6、STW的说明

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

-XX:+PrintSafepointStatistics 打印安全点统计信息，

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

6.1 日志分析：

1. vmop： 引起STW的缘由，以及触发时间，本例中是GC。该项常见的输出有：RevokeBias、BulkRevokeBias、Deoptimize、G1IncCollectionPause。

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

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

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

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

5. sync = spin + block + 其余。

6.2 由日志能够看出，safepoint的执行分为四个阶段：

1. Spin阶段。由于jvm在决定进入全局safepoint的时候，有的线程在安全点上，而有的线程不在安全点上，这个阶段是等待未在安全点上的用户线程进入安全点。
2. Block阶段。即便进入safepoint，用户线程这时候仍然是running状态，保证用户不在继续执行，须要将用户线程阻塞。
3. Cleanup。这个阶段是JVM作的一些内部的清理工做。
4. 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

7、引发长时间STW缘由

• GC
• RevokeBias 撤销偏向锁操做也会消耗很长时间。在高并发系统中，建议禁用偏向锁。
• 百分之九十的状况都是以上2个缘由。

8、现场

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

果真是撤销偏向锁搞得鬼，增长 -XX:-UseBiasedLocking 后，问题获得解决.