通过JVM日志来进行安全点分析

标签: JAVA JVM | 发表时间:2015-05-25 11:39 | 作者:-之诸暇
出处:http://ifeve.com

原文链接 作者: Plumbr 译者:之诸暇

许多事件都可能会导致JVM暂停所有的应用线程。这类暂停又被称为”stop-the-world”(STW)暂停。触发STW暂停最常见的原因就是垃圾回收了( github中的一个例子),但不同的JIT活动( 例子),偏向锁擦除( 例子), 特定的JVMTI操作,以及许多场景也可能会导致应用程序暂停。

应用程序线程可以被安全地停止掉的那个时间点,就叫做安全点。这一术语也通常用来指代SWT暂停。

通常来讲GC日志都是打开的。然而,并非所有安全点的信息都能完整地记录下来。想获取到完整的日志,可以使用下列的JVM选项:


-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime

从参数名字来看你可能会觉得是与GC相关的,其实不然——打开这些选项能够记录下所有的安全点,而不止是GC暂停的。如果你用上述的选项来运行下这个例子( github源码

你会在标准输出中看到如下信息:


Application time: 0.3440086 seconds
Total time for which application threads were stopped: 0.0620105 seconds
Application time: 0.2100691 seconds
Total time for which application threads were stopped: 0.0890223 seconds


很通俗易懂(和GC日志相比来说)——从中你可以得知应用程序在前344毫秒中是在处理实际工作的,然后将所有线程暂停了62毫秒,紧接着又工作了210ms,然后又暂停了89ms。

你还可以将这些选项与GC的选项结合起来使用,比如将上面这个程序加上-XX:+PrintGCDetails 选项后再运行一次,输出则变成这样了;


[Full GC (Ergonomics) [PSYoungGen: 1375253K->0K(1387008K)] [ParOldGen: 2796146K->2049K(1784832K)] 4171400K->2049K(3171840K), [Metaspace: 3134K->3134K(1056768K)], 0.0571841 secs] [Times: user=0.02 sys=0.04, real=0.06 secs] 
Total time for which application threads were stopped: 0.0572646 seconds, Stopping threads took: 0.0000088 seconds

综上可知,应用线程被强制暂停了57ms来进行垃圾回收。其中又有8ms是用来等待所有的应用线程都到达安全点。如果我们用同样的选项运行另一个例子( Github源码)的话,输出又变成这样的了:


Total time for which application threads were stopped: 0.0001273 seconds, Stopping threads took: 0.0000196 seconds
Total time for which application threads were stopped: 0.0000648 seconds, Stopping threads took: 0.0000174 seconds

光从这些信息我们无从得知是什么导致的暂停,因为看不出有任何的垃圾回收的活动。如果你想更详细地了解安全点的信息的话,可以使用这组JVM参数:


-XX:+PrintSafepointStatistics  -XX:PrintSafepointStatisticsCount=1

启用这些参数使得JVM会将一些额外的信息记录到标准输出中,大概类似这样:


5.141: RevokeBias                       [      13          0              2    ]      [     0     0     0     0     0    ]  0  
Total time for which application threads were stopped: 0.0000782 seconds, Stopping threads took: 0.0000269 seconds

关于安全点的信息是按照如下的顺序进行显示的:

– JVM启动之后所经历的毫秒数(上例中是5.141)
– 触发这次暂停的操作名(RevokeBias)。
如果你看见”no vm operation”,就说明这是一个”保证安全点”。JVM默认每秒会触发一次安全点来处理那些非紧急的排队的操作。GuaranteedSafepointInterval选项可以用来调整这一行为(设置为0的话就会禁用该功能)
– 停在安全点的线程的数量(13)
– 在安全点开始时仍在运行的线程的数量(0)
– 虚拟机操作开始执行前仍处于阻塞状态的线程的数量(2)
– 到达安全点时的各个阶段以及执行操作所花的时间(0)

因此我们可以看出,使用了偏向锁会导致大量的STW暂停,尽管它们只花了几十毫秒。在如今这个大量使用并发的年代,禁用它们也不是什么罕见的事情。

不管怎样,多打印些日志总会减少一些麻烦事的。你可以使用如下的JVM参数:


-XX:+LogVMOutput -XX:LogFile=vm.log

所有的虚拟机日志都会输出到vm.log文件中。如何解读这些日志并做出响应是一个很大的课题,这已经远超本文所讨论的范围了,不过未来我仍会更新一到两篇文章来讲下这个,请拭目以待.

英文原文链接

本文同时发表在我的个人博客: Java译站

原创文章,转载请注明: 转载自 并发编程网 – ifeve.com

本文链接地址: 通过JVM日志来进行安全点分析

相关 [jvm 日志 安全] 推荐:

通过JVM日志来进行安全点分析

- - 并发编程网 - ifeve.com
原文链接 作者: Plumbr 译者:之诸暇. 许多事件都可能会导致JVM暂停所有的应用线程. 这类暂停又被称为”stop-the-world”(STW)暂停. 触发STW暂停最常见的原因就是垃圾回收了( github中的一个例子),但不同的JIT活动( 例子),偏向锁擦除( 例子), 特定的JVMTI操作,以及许多场景也可能会导致应用程序暂停.

JVM致命错误日志(hs_err_pid.log)解读

- - 四火的唠叨
文章系本人原创,转载请保持完整性并注明出自 《四火的唠叨》. 致命错误出现的时候,JVM生成了hs_err_pid.log这样的文件,其中往往包含了虚拟机崩溃原因的重要信息. 因为经常遇到,在这篇文章里,我挑选了一个,并且逐段分析它包含的内容(文件可以在文章最后下载). 默认情况下文件是创建在工作目录下的(如果没权限创建的话JVM会尝试把文件写到/tmp这样的临时目录下面去),当然,文件格式和路径也可以通过参数指定,比如:.

JVM日志和参数的理解

- - 开源软件 - ITeye博客
转自:http://hot66hot.iteye.com/blog/2075819. 写这篇wiki的目的:最近在调整Hbase的JVM,翻了些文档和wiki,想写点东西,给自己和想了解jvm日志和参数的同 学提供些帮助..  一:理解GC日志格式,读GC日志的方法. -XX:+UseGCLogFileRotation  启用GC日志文件的自动转储 (Since Java).

Fatal Error log format,JVM 致命错误日志格式

- - 码蜂笔记
本文翻译自: http://www.oracle.com/technetwork/java/javase/felog-138657.html. 本文内容基于 Java SE 6,HotSpot JVM. 当一个致命错误发生时,一个错误日志将被创建,存储了在致命错误发生时获取到的信息和状态. 注意:这个文件的格式可能随着版本的更新而改变.

JVM研究

- - 开源软件 - ITeye博客
每天接客户的电话都是战战兢兢的,生怕再出什么幺蛾子了. 我想Java做的久一点的都有这样的经历,那这些问题的最终根结是在哪呢. JVM全称是Java Virtual Machine,Java虚拟机,也就是在计算机上再虚拟一个计算机,这和我们使用 VMWare不一样,那个虚拟的东西你是可以看到的,这个JVM你是看不到的,它存在内存中.

jvm调优

- - 互联网 - ITeye博客
printf "%x\n" 21742  找到耗时最长的进程. jstack pid | grep 54ee  定位某个类的方法. jstack 10535|grep -A 10 2a1d (最后十行). jmap 查询pid 内存线程. 附:TOP命令中需要关注的值:. (1)load average:此值反映了任务队列的平均长度;如果此值超过了CPU数量,则表示当前CPU数量不足以处理任务,负载过高.

学习JVM的References

- LightingMan - 淘宝JAVA中间件团队博客
本blog中列举了我学习JVM的references,会不断的更新,为了避免版权问题,就不在blog上提供references的下载了,感兴趣的同学可自行下载或购买,:). |— [ Hotspot GC论文 ]. |— [ 其他JVM GC ]. |— Linux内核源代码情景分析. |— Linux 内核中断内幕.

深入理解JVM

- 小伟 - ITeye论坛最新讨论
1   Java技术与Java虚拟机. 说起Java,人们首先想到的是Java编程语言,然而事实上,Java是一种技术,它由四方面组成: Java编程语言、Java类文件格式、Java虚拟机和Java应用程序接口(Java API). 图1   Java四个方面的关系. 运行期环境代表着Java平台,开发人员编写Java代码(.java文件),然后将之编译成字节码(.class文件).

jvm垃圾回收

- Cano - 淘宝共享数据平台 tbdata.org
在jvm中堆空间划分为三个代:年轻代(Young Generation)、年老代(Old Generation)和永久代(Permanent Generation). 年轻代和年老代是存储动态产生的对象. 永久带主要是存储的是java的类信息,包括解析得到的方法、属性、字段等等. 我们这里讨论的垃圾回收主要是针对年轻代和年老代.