阅读 1412

(干货篇) 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的下面。

三、安全点是什么

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

有关安全点的详细说明,请移步:

JVM源码分析之安全点safepoint

[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 日志分析:
  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

七、引起长时间STW原因

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

八、现场

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

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