花钱的年华

江南白衣,公众号:春天的旁边

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

| Filed under 技术

什么是安全点

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

JVM里有一条特殊的线程--VM Threads,专门用来执行一些特殊的VM Operation,比如分派GC的STW,thread dump等,这些任务,都需要整个Heap,以及所有线程的状态是静止的,一致的才能进行。所以JVM引入了安全点(Safe Point)的概念,想办法在需要进行VM Operation时,通知所有的线程进入一个静止的安全点。 如何做到的见 聊聊JVM(九)理解进入safepoint时如何让Java线程全部阻塞

除了GC,其他触发安全点的VM Operation包括:

  • 1. JIT相关,比如Code deoptimization, Flushing code cache
  • 2. Class redefinition (e.g. javaagent,AOP代码植入的产生的instrumentation)
  • 3. Biased lock revocation 取消偏向锁
  • 4. Various debug operation (e.g. thread dump or deadlock check)

打开JDK7源码的vm_operations.hpp,有一个长长的列表,比如ReportJavaOutOfMemory等等不能尽录。

 

监控安全点

是不是看得心里发毛,马上就想监控下自己的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

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

但是,在JDK1.7.40以前的版本,它居然没有打印时间戳,所以只能知道JVM停了多久,但不知道什么时候停的。此时一个土办法就是加多一句“ -XX:+PrintGCApplicationConcurrentTime”,打印JVM在两次停顿之间的正常运行时间(同样没有时间戳),但好歹能配合有时间戳的GC日志,反推出Stop发生的时间了。

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

 

怎么进的安全点?

好,我现在知道有什么停顿了,但怎么知道因为上面列的哪种原因而停顿呢?
特别是,怎么好像多了很多时间非常非常短的没有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: 安全点里的总线程数
  • initially_running: 安全点时开始时正在运行状态的线程数
  • wait_to_block: 在VM Operation开始前需要等待其暂停的线程数

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

  • spin: 等待线程响应safepoint号召的时间
  • block: 暂停所有线程所用的时间
  • sync: 等于 spin+block,这是从开始到进入安全点所耗的时间,可用于判断进入安全点耗时
  • cleanup: 清理所用时间
  • vmop: 真正执行VM Operation的时间

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

另外还看到有些类型是no vm operation, 文档上说是保证每秒都有一次进入安全点(如果这秒已经GC过就不用了),给一些需要在安全点里进行,又非紧急的操作使用,比如一些采样型的Profiler工具,可用-DGuaranteedSafepointInterval来调整,不过实际看它并不是每秒都会发生,时间不定。

 

那长期打开安全点日志如何?

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

但是,

1. 安全点日志默认输出到stdout,一是stdout日志的整洁性,二是stdout所重定向的文件如果不在/dev/shm,可能被锁。
2. 对于一些很短的停顿,比如取消偏向锁,打印的消耗比停顿本身还大。
3. 安全点日志是在安全点内打印的,本身加大了安全点的停顿时间。

所以并不建议默认长期打开,只在问题排查时打开。

 

把安全点日志打印到独立文件

如果在生产系统上要打开,再再增加下面四个参数:

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

打开Diagnostic(只是开放了更多的flag可选,不会主动激活某个flag),关掉输出VM日志到stdout,输出到独立文件,我最喜欢的/dev/shm目录(内存文件系统)。

 

结论

  1. -XX:+PrintGCApplicationStoppedTime 很重要,一定要打开。
  2. 取消偏向锁
  3. 只在排查问题时打开安全点日志

 

参考资料

我部内置研究院的薛院长对本文亦有贡献,转载请保留原文链接: http://calvin1978.blogcn.com/articles/safepoint.html

Tim那天在群里说打猎去了,遥想英姿,配图一二。

有关的...

发表评论

您的电子邮箱不会被公开。

您可以使用这些 HTML 标签和属性: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>