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

本文涉及的产品
日志服务 SLS,月写入数据量 50GB 1个月
简介:

许多事件都可能会导致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文件中。










本文转自 小强测试帮 51CTO博客,原文链接:http://blog.51cto.com/xqtesting/1971579,如需转载请自行联系原作者
相关实践学习
日志服务之使用Nginx模式采集日志
本文介绍如何通过日志服务控制台创建Nginx模式的Logtail配置快速采集Nginx日志并进行多维度分析。
目录
相关文章
|
2天前
|
SQL 关系型数据库 MySQL
MySQL事务日志-Undo Log工作原理分析
事务的持久性是交由Redo Log来保证,原子性则是交由Undo Log来保证。如果事务中的SQL执行到一半出现错误,需要把前面已经执行过的SQL撤销以达到原子性的目的,这个过程也叫做"回滚",所以Undo Log也叫回滚日志。
MySQL事务日志-Undo Log工作原理分析
|
10天前
|
存储 运维 监控
Linux--深入理与解linux文件系统与日志文件分析
深入理解 Linux 文件系统和日志文件分析,对于系统管理员和运维工程师来说至关重要。文件系统管理涉及到文件的组织、存储和检索,而日志文件则记录了系统和应用的运行状态,是排查故障和维护系统的重要依据。通过掌握文件系统和日志文件的管理和分析技能,可以有效提升系统的稳定性和安全性。
27 7
|
12天前
|
监控 安全 Linux
启用Linux防火墙日志记录和分析功能
为iptables启用日志记录对于监控进出流量至关重要
|
1月前
|
监控 应用服务中间件 定位技术
要统计Nginx的客户端IP,可以通过分析Nginx的访问日志文件来实现
要统计Nginx的客户端IP,可以通过分析Nginx的访问日志文件来实现
|
2月前
|
监控 算法 Java
jvm-48-java 变更导致压测应用性能下降,如何分析定位原因?
【11月更文挑战第17天】当JVM相关变更导致压测应用性能下降时,可通过检查变更内容(如JVM参数、Java版本、代码变更)、收集性能监控数据(使用JVM监控工具、应用性能监控工具、系统资源监控)、分析垃圾回收情况(GC日志分析、内存泄漏检查)、分析线程和锁(线程状态分析、锁竞争分析)及分析代码执行路径(使用代码性能分析工具、代码审查)等步骤来定位和解决问题。
|
3月前
|
存储 缓存 关系型数据库
MySQL事务日志-Redo Log工作原理分析
事务的隔离性和原子性分别通过锁和事务日志实现,而持久性则依赖于事务日志中的`Redo Log`。在MySQL中,`Redo Log`确保已提交事务的数据能持久保存,即使系统崩溃也能通过重做日志恢复数据。其工作原理是记录数据在内存中的更改,待事务提交时写入磁盘。此外,`Redo Log`采用简单的物理日志格式和高效的顺序IO,确保快速提交。通过不同的落盘策略,可在性能和安全性之间做出权衡。
1746 14
MySQL事务日志-Redo Log工作原理分析
|
2月前
|
存储 SQL 监控
|
2月前
|
运维 监控 安全
|
2月前
|
监控 关系型数据库 MySQL
分析慢查询日志
【10月更文挑战第29天】分析慢查询日志
53 3
|
2月前
|
监控 关系型数据库 数据库
怎样分析慢查询日志?
【10月更文挑战第29天】怎样分析慢查询日志?
66 2