SEO外包平台,我们为您提供专业的企业网站SEO整站优化外包服务 SEO设置

SEO外包平台

专注于企业网站SEO整站优化外包服务

JVM 技术详解:GC 日志解读与分析(实例分析上篇)

作者:jcmp      发布时间:2021-04-18      浏览量:0
在 JDK 9 之后的版本中,启动参数有

在 JDK 9 之后的版本中,启动参数有一些变化,继续使用原来的参数配置可能会在启动时报错。不过也不用担心,如果碰到,一般都可以从错误提示中找到对应的处置措施和解决方案。

例如 JDK 11 版本中打印 info 级别 GC 日志的启动脚本:

# JDK 11 环境,输出 info 级别的 GC 日志java -Xms512m -Xmx512m-Xlog:gc*=info:file=gc.log:time:filecount=0demo.jvm0204.GCLogAnalysis。

从 JDK 9 开始,可以使用命令 java -Xlog:help 来查看当前 JVM 支持的日志参数,本文不进行详细的介绍,有兴趣的同学可以查看 JEP 158: Unified JVM Logging 和 JEP 271: Unified GC Logging 。

另外 ,JMX 技术提供了 GC 事件的通知机制,监听 GC 事件的示例程序我们会在《应对容器时代面临的挑战》这一章节中给出。

但很多情况下 JMX 通知事件中报告的 GC 数据并不完全,只是一个粗略的统计汇总。

GC 日志才是我们了解 JVM 和垃圾收集器最可靠和全面的信息,因为里面包含了很多细节。再次强调,分析 GC 日志是一项很有价值的技能,能帮助我们更好地排查性能问题。

下面我们通过实际操作来分析和解读 GC 日志。

Serial GC 日志解读

关于串行垃圾收集器的介绍,请参考前面的文章:《常见 GC 算法介绍》。

首先,为了打开 GC 日志记录,我们使用下面的 JVM 启动参数如下:

# 请注意命令行启动时没有换行,此处是手工排版java -XX:+UseSerialGC-Xms512m -Xmx512m-Xloggc:gc.demo.log-XX:+PrintGCDetails-XX:+PrintGCDateStampsdemo.jvm0204.GCLogAnalysis。

让我们看看 Serial GC 的垃圾收集日志,并从中提取信息。

启用串行垃圾收集器,程序执行后输出的 GC 日志类似这样(为了方便大家阅读,已手工折行):

Java HotSpot(TM) 64-Bit Server VM (25.162-b12) ......Memory: 4k page,physical 16777216k(1551624k free)CommandLine flags: -XX:InitialHeapSize=536870912 -XX:MaxHeapSize=536870912 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseSerialGC2019-12-15T15:18:36.592-0800: 0.420: [GC (Allocation Failure) 2019-12-15T15:18:36.592-0800: 0.420: [DefNew: 139776K->17472K(157248K),0.0364555 secs] 139776K->47032K(506816K), 0.0365665 secs] [Times: user=0.02 sys=0.01,real=0.03 secs]......2019-12-15T15:18:37.081-0800: 0.908: [GC (Allocation Failure) 2019-12-15T15:18:37.081-0800: 0.908: [DefNew: 156152K->156152K(157248K),0.0000331 secs] 2019-12-15T15:18:37.081-0800: 0.908: [Tenured: 299394K->225431K(349568K),0.0539242 secs] 455546K->225431K(506816K), [Metaspace: 3431K->3431K(1056768K)], 0.0540948 secs] [Times: user=0.05 sys=0.00,real=0.05 secs]

日志的第一行是 JVM 版本信息,第二行往后到第一个时间戳之间的部分,展示了内存分页、物理内存大小,命令行参数等信息,这部分前面介绍过,不在累述。

仔细观察,我们发现在这段日志中发生了两次 GC 事件,其中一次清理的是年轻代,另一次清理的是整个堆内存。让我们先来分析前一次年轻代 GC 事件。

Minor GC 日志分析

这次年轻代 GC 事件对应的日志内容:

2019-12-15T15:18:36.592-0800: 0.420: [GC (Allocation Failure) 2019-12-15T15:18:36.592-0800: 0.420: [DefNew: 139776K->17472K(157248K),0.0364555 secs] 139776K->47032K(506816K), 0.0365665 secs] [Times: user=0.02 sys=0.01,real=0.03 secs]

从中可以解读出这些信息:

凭经验,这个暂停时间对大部分系统来说可以接受,但对某些延迟敏感的系统就不太理想了,比如实时的游戏服务、高频交易业务,30ms 暂停导致的延迟可能会要了亲命。

这样解读之后,我们可以分析 JVM 在 GC 事件中的内存使用以及变化情况。

在此次垃圾收集之前,堆内存总的使用量为 139776K,其中年轻代使用了 139776K。可以算出,GC 之前老年代空间的使用量为 0。(实际上这是 GC 日志中的第一条记录)。

这些数字中蕴含了更重要的信息:

可以算出,从年轻代提升到老年代的对象占用了 “122304K-92744K=29560K” 的内存空间。当然,另一组数字也能推算出 GC 之后老年代的使用量:47032K-17472K=29560K。

此次 GC 事件的示意图如下所示:

Full GC 日志分析

分析完第一次 GC 事件之后,我们心中应该有个大体的模式了。一起来看看另一次 GC 事件的日志:

2019-12-15T15:18:37.081-0800: 0.908: [GC (Allocation Failure) 2019-12-15T15:18:37.081-0800: 0.908: [DefNew: 156152K->156152K(157248K),0.0000331 secs] 2019-12-15T15:18:37.081-0800: 0.908: [Tenured: 299394K->225431K(349568K),0.0539242 secs] 455546K->225431K(506816K), [Metaspace: 3431K->3431K(1056768K)], 0.0540948 secs] [Times: user=0.05 sys=0.00,real=0.05 secs]

从中可以解读出这些信息: