JVM的Stop The World，安全点，黑暗的地底世界

 

一、什么是安全点

GC时的Stop the World(STW)是大家最大的敌人。但可能很多人没留意，除了GC，JVM底下还会发生这样那样的停顿。

JVM里有一条特殊的线程－－VM Thread，专门用来执行一些特殊的VM Operation，比如thread dump等，这些任务，都需要整个Heap，以及所有线程的状态是静止的、一致的才能进行。所以JVM引入了安全点(Safe Point)的概念。

除了GC，其他触发安全点的VM Operation包括：

1. Biased lock revocation 取消偏向锁

2. Class redefinition (e.g. javaagent，AOP的代码植入)

3. Various debug operation (e.g. thread dump 一条或所有线程，heapduump等)

打开JDK8源码的vm_operations.hpp，有长长的完整58项列表。

V2.0版说明

最烦网上尽是过期文章，于是重新把这篇两年前的文章捡回来更新了一把，又加入了进入机制的硬知识，和监控的黑科技。

二、查看安全点

是不是看得心里发毛，马上就想查看下自己的JVM到底发生了什么？

最简单的做法，在JVM启动参数的GC参数里，多加一句:

-XX:+PrintGCApplicationStoppedTime

它就会把JVM的停顿时间（不只是GC），打印在GC日志里。

2016-08-22T00:19:49.559+0800: 219.140: Total time for which application threads were stopped: 0.0053630 seconds

这真是个很有用很有用的必配参数，真正忠实的打出，几乎一切的停顿。。。。

2016-08-22T00:19:50.183+0800: 219.764: Application time: 5.6240430 seconds

来自两年后的更新： 说几乎，是这里涵盖了JVM所有被设计的、主动的停顿。两年时间里，我们还是遇到一些意料之外的情况，比如之前那篇JNI的内存共享，我们就曾经玩坏过，而停顿时间并没有被纪录。

三、为什么进的安全点？

好，我现在知道有什么停顿了，但怎么知道因为上面列的哪种原因而停顿呢？

特别是，怎么好像多了很多时间非常非常短的没有GC日志伴随的停顿？

那，再多加两个参数：

-XX:+PrintSafepointStatistics -XX: PrintSafepointStatisticsCount＝1

此时，在stdout中会打出类似的内容：

vmop [threads: total initially_running wait_to_block]

1913.425: GenCollectForAllocation [ 55 2 0 ]

[time: spin block sync cleanup vmop] page_trap_count

[ 0 0 0 0 6 ] 0

此日志分两段，第一段是时间戳，VM Operation的类型，以及线程概况

• total: 所有的java线程数
• initially_running: 号召进入安全点时，还是Running状态的线程数
• wait_to_block: 所有线程都不Running时，仍不是Block状态的线程数

第二段是到达安全点的各个阶段以及执行操作所花的时间，其中最重要的是vmop

• spin: VMOP线程使用自旋，等待所有线程都不是Running的时间
• block: VMOP线程基于锁，等待所有线程都是Block的时间
• sync: spin+block +其他，这是从开始到进入安全点的总耗时
• cleanup: 退出清理所用时间
• vmop: 真正执行VM Operation的时间

两年后的更新：对着safepoint.cpp的代码，修改了一次描述，网上不少文章复制了上一版的描述，惭愧。

噢，原来那些很多但又很短的安全点，全都是RevokeBias，详见《偏向锁实现原理》， 高并发的应用一般会干脆在启动参数里加一句"-XX:-UseBiasedLocking"取消掉它。

另外还看到有些类型是no vm operation， 给一些需要在安全点里进行，又非紧急的操作使用，如果这段时间里，VM都没有因为GC等原因进入过安全点，就强制进入一下。

四、那长期打开安全点日志如何？

在实战中，我们利用安全点日志，发现过有程序定时调用Thread Dump等等情况。

但是，安全点日志默认输出到stdout，一是影响stdout日志的整洁性；二是输出到stdout所重定向的文件时可能被IO锁，延长了安全点的停顿时间；三是像取消偏向锁这样很短的停顿，打印的消耗比停顿本身还大。

所以，如果已经取消了偏向锁，而且将安全日志单独输出到/dev/shm 内存文件系统中。那为了排查问题，开一段时间也是没问题的。

-XX:+UnlockDiagnosticVMOptions -XX:-DisplayVMOutput -XX:+LogVMOutput -XX:LogFile=/dev/shm/vm.log

参数解释：打开Diagnostic选项（后两者需要），关掉输出VM信息到stdout，而是把它输出到/dev/shm里。

五、线程们进入安全点的硬知识

为什么要给我看这么硬的东西～～

假如你在安全点日志里，发现sync那段的时间很长的话，了解原理的话，起码可以缓解下内心的恐惧（虽然未必能找出原因来）

1. 运行中的线程是如何听到召唤的

VM线程要发起号召，就把特定某一页内存置为不可读的状态。

然后那些运行中的线程经过检查点的时候，就会执行一次检查: 类似“test %eax,0x160100”的指令去测试这页内存，收获一个满满恶意的SEGV信号。

这个信号的处理方式，就是线程调用SafepointSynchronize的block()方法把自己停下来。

2. 检查点／收费站是如何建立起来的

在字节码解释执行状态，解释器会很经常地做检查；

如果已经被JIT编译成二进制码，编译器会在每个函数退出时增加检查，在每个“uncounted-loop“的循环边上作出检查。

举些例子吧：

// 因为是counted-loop，循环没有检查点，只有等它执行完才会进入安全点，其他线程要痛苦等待它。

for (int i=0; i<100; i++) {

a++;

}

// 虽然循环里没有检查点，但foo() 方法退出时会有检查点

for (int i=0;i<10;i++) {

foo();

}

// 怒啊，假如循环里那个方法被内联了，检查点又没了

for (int i=0; i<10; i++) {

inlineableMethod();

}

//这种条件循环，属于uncountd-loop，有检查点。

while (a!=0) {

b++;

}

// 把循环子int 改为long，也被认为是uncountd-loop，也有检查点了。

for (long i=0;i<10L; i++) {

a++;

}

可见，长的for循环可能是让线程迟迟不进入安全点。

如果CPU竞争，线程也会比较晚才抢到CPU执行检查 和 Blocking。

3. 不用等谁

a. 非Java的线程不需要

b. 运行在JNI状态的线程不需要，因为它在做的事情不影响Java代码，当它想回到Java态时，会有检查点把它拦下来的。

c. A thread blocked on a lock or synchronized block, waiting on a monitor, parked, or blocked on blocking IO，因为大家都停了，也就没人去唤醒这些条件。

六、监控安全点的黑科技，排查请求超时的利器。

如果能在监控系统上显示JVM进入安全点的次数和时间，那我们排查服务超时时就可以第一时间先上监控系统观察下当时JVM停顿时间的情况。

1. 在应用里往外吐信息

hotspot 里提供里一个API，但是没挂到JMX上，所以只适合由泡在应用里的代码往外吐。

import sun.management.*

private static HotspotRuntimeMBean mbean = (HotspotRuntimeMBean)ManagementFactoryHelper.getHotspotRuntimeMBean();

long count = mbean.getSafepointCount();

long time = mbean.getTotalSafepointTime();

long syncTime = mbean.getSafepointSyncTime()

2. 在应用外部利用PerfData获取信息

利用JVM每秒写的PerfData，详见《围绕JVM的各种外挂技术》，具体实现可以抄一下我们家vjtop的实现代码 ( https://github.com/vipshop/vjtools/)

小结

1. -XX:+PrintGCApplicationStoppedTime 很重要，一定要打开。
2. 取消偏向锁
3. 在排查问题时，可长期打开安全点日志
4. 完善监控体系，将安全点纳入