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

原文链接 作者: 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文件中。如何解读这些日志并做出响应是一个很大的课题,这已经远超本文所讨论的范围了,不过未来我仍会更新一到两篇文章来讲下这个,请拭目以待.

时间: 2024-08-31 13:42:52

通过JVM日志来进行安全点分析的相关文章

web工程发布到新浪sae上出现503错误,麻烦帮我看一下JVM 日志

问题描述 web工程发布到新浪sae上出现503错误,麻烦帮我看一下JVM 日志 [29/Nov/2014:17:08:30 +0800] JAVA_Error: Failed startup of context c.s.s.w.SaeWebAppContext{/wuareyoung-1file:/data1/jetty_work/671/wuareyoung/jetty-0.0.0.0-12907-wuareyoung.war-_wuareyoung-1-any-/webapp/}/dat

Android日志系统Logcat源代码简要分析

在前面两篇文章Android日志系统驱动程序Logger源代码分析和Android应用程序框架层和系统运行库层日志系统源代码中,介绍了Android内核空间层.系统运行库层和应用程序框架层日志系统相关的源代码,其中,后一篇文章着重介绍了日志的写入操作.为了描述完整性,这篇文章着重介绍日志的读取操作,这就是我们在开发Android应用程序时,经常要用到日志查看工具Logcat了.         Logcat工具内置在Android系统中,可以在主机上通过adb logcat命令来查看模拟机上日志

路由器配置日志信息地发送选项分析 下篇

将日志信息存储到其他存储区域之前介绍的将日志信息发送到线路这种方式存在一个弊端,如果我们没有看到连接线路的屏幕输出,消息滚过屏幕并超出了终端软件的历史缓存, 那么我们将无法在看到那些丢失的消息.为了避免这个问题,我们经常会将日志信息发送到别的存储区域,包括设备内部缓存, 系统日志服务器, SNMP管理终端.1) 将日志信息保存到log服务器如果想将日志信息发送到设备的内部缓存中,则使用如下的命令:hostname(config)#loggingbuffered[buffer_size|secur

使用awk命令对IBM HTTP Server的日志进行快速有效的分析

IBM HTTP Server 是基于 http://www.aliyun.com/zixun/aggregation/14417.html">Apache Web Server 之上开发的一个多功能 Web 服务器.IBM HTTP Server 扩展了 Apache 的功能,引入了一些 Apache 没有的功能.比如,能够使用 IBM 快速响应高速缓存加速器,以及更方便的与 IBM WebSphere 其他产品进行集成.为了了解 IBM HTTP Server 的运行状况,需要对 IB

Android日志系统驱动程序Logger源代码分析

  我们知道,在Android系统中,提供了一个轻量级的日志系统,这个日志系统是以驱动程序的形式实现在内核空间的,而在用户空间分别提供了Java接口和C/C++接口来使用这个日志系统,取决于你编写的是Android应用程序还是系统组件.在前面的文章浅谈Android系统开发中LOG的使用中,已经简要地介绍了在Android应用程序开发中Log的使用方法,在这一篇文章中,我们将更进一步地分析Logger驱动程序的源代码,使得我们对Android日志系统有一个深刻的认识.         既然And

Shell脚本实现apache日志中的状态码分析_linux shell

一.首先将apache日志按天切割 复制代码 代码如下:        vi /etc/httpd/conf/httpd.conf         ErrorLog "|rotatelogs /var/log/httpd/%Y%m%derror_log 86400 480"        CustomLog "|rotatelogs /var/log/httpd/%Y%m%daccess_log 86400 480" combined 二.重启apache服务 复制

支付行业,如何通过日志大数据实现深度分析及风控

本文主要讲述针对支付行业,日志易产品如何通过日志大数据实现业务深度分析及风险控制. 伴随新的支付方式出现,近年来移动支付蓬勃发展,如何分析.利用海量交易数据,已成为当前支付企业面对的巨大难题.日志作为数据的载体,蕴含着丰富的信息,传统的日志分析方式低效而固化,无法应对数据体量大.格式不统一.增长速度快的现状,在交易出现异常及失败时,更难以满足实时处理.快速响应的需求.本文讲述某支付公司采用日志易后,通过日志大数据实现业务深度分析及风险控制的实践经验. 图片来自:前瞻网 本次分享结合企业自身对支付

基于JVM 调优的技巧总结分析_java

这篇是技巧性的文章,如果要找关于GC或者调整内纯的文章,看我其他几篇文章.因为是JVM 调优总结,所以废话少说.从各方面一共收集到以下几个方法:1.升级 JVM 版本.如果能使用64-bit,使用64-bit JVM.    基本上没什么好解释的,很简单将JVM升级到最新的版本.如果你还是使用JDK1.4甚至是更早的JVM,那你首先要做的就是升级.因为JVM从1.4- >1.5->1.6可不是仅仅的版本号升级,或者仅仅往里面加了一堆新的语言特性,这么简单.而是真正在JVM做了重大的改进,每次版

log4j中配置日志文件相对路径方法分析

  方法一. 解决的办法自然是用相对路径代替绝对路径,其实log4j的FileAppender本身就有这样的机制,如:log4j.appender.logfile.File=${WORKDIR}/logs/app.log其中"${WORKDIR}/"是个变量,会被System Property中的"WORKDIR"的值代替.这样,我们就可以在log4j加载配置文件之前,先用System.setProperty ("WORKDIR", WORKDI