一、遇到的问题
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的时候要挂起所有活动的线程，因此线程挂起，会选择在到达安全点的时候挂起。
- 安全点这个特殊的位置保存了线程上下文的全部信息。说白了，在进入安全点的时候打印日志信息能看出线程此刻都在干嘛。
有关安全点的详细说明，请移步：
[Java JVM] Hotspot GC研究- GC安全点 (Safepoint&Stop The World)
四、什么是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 后，问题得到解决.
