栏目分类:
子分类:
返回
名师互学网用户登录
快速导航关闭
当前搜索
当前分类
子分类
实用工具
热门搜索
名师互学网 > IT > 软件开发 > 后端开发 > Java

手撕 JVM 垃圾收集日志

Java 更新时间: 发布时间: IT归档 最新发布 模块sitemap 名妆网 法律咨询 聚返吧 英语巴士网 伯小乐 网商动力

手撕 JVM 垃圾收集日志

分析背景

本篇的全部内容都基于 JDK 8 Hotspot JVM,分别从 ParallelGC 、CMS、G1 三种常用的垃圾收集器来分析。可以通过下图查看三种垃圾收集器的对应关系,分别对应图中标示的 1、2、3。

为了方便日志分析,我设置了一下简单的 JVM 作为基础参数,其中年轻代 10M,老年代 10M,堆大小 20M。

-Xms20M

-Xmx20M

-Xmn10M

-XX:SurvivorRatio=8

-XX:MetaspaceSize=6M

-XX:MaxMetaspaceSize=6M

-XX:+HeapDumpOnOutOfMemoryError

-XX:HeapDumpPath=/Users/fengzheng/jvmlog

简单日志格式

通过参数 -verbose:gc 或者 -XX:+PrintGC 可以让 JVM 开启简单日志格式,对于这几种垃圾收集期,简单日志的格式都是一致的。简单日志内容很少,只有GC类型(标示是 Minor GC 还是 Full GC)、GC 原因、堆收集前和收集后大小、堆的总大小以及收集耗时。

下面是简单日志配置下的几条收集日志,包括正常的空间分配失败引起的收集、System.gc() 触发的垃圾收集、以及执行 jmap -histo:live pid 命令执行的垃圾收集。

Minor GC 新生代 GC

[GC (Allocation Failure) 7164K->704K(19456K), 0.0017002 secs]

System.gc() 触发 Full GC

[GC (System.gc()) 4157K->648K(19456K), 0.0019522 secs]

[Full GC (System.gc()) 648K->609K(19456K), 0.0099904 secs]

jmap -histo:live 触发 Full GC

[GC (Heap Inspection Initiated GC) 938K->737K(19456K), 0.0009119 secs]

[Full GC (Heap Inspection Initiated GC) 737K->573K(19456K), 0.0070892 secs]

下图说明了一条简单格式的垃圾收集日志各个字段的含义。

在实际的生产环境中,只用简单格式的 JVM 日志意义不大,得到的有用信息不多,也就是知道垃圾收集次数、收集耗时以及堆的使用量,对于排查分析问题的帮助不是很大,所以,一般都会配置更加详细的日志格式。

详细日志格式

使用 -XX:+PrintGCDetails和-XX:+PrintGCDateStamps 这两个参数可以打印详细的垃圾收集日志和垃圾收集的时间戳。当然了,除了这两个之外,还有一些更具体的参数,比如收集前后打印堆使用信息的 -XX:+PrintHeapAtGC参数等等。

当然了,参数配置的越多,打印的信息越是详细,对于排查问题越有帮助,就是内容就会变得很多,肉眼看起来会比较抓狂。

Parallel Scavenge 收集器

在 JDK 8 中,如果不指定垃圾收集器,默认是使用参数 -XX:+UseParallelGC 的,也就是新生代使用 Parallel Scavenge,老年代配合使用的是 Serial Old。

Parallel Scavenge是一款并行的、高吞吐量的垃圾收集器,采用复制算法。适用于追求高效率的、对即时响应要求不高的系 Java开源项目【ali1024.coding.net/public/P7/Java/git】 统。

要了解清楚 GC 日志各部分的含义,就要了解 JVM 内存模型以及垃圾收集器对于内存的规划和管理情况,老样子,还是通过图来看一下比较清楚。JDK 8 支持的除 G1 外的垃圾收集器,都适用此图,包括下面要介绍的 CMS。

垃圾收集的部分即是上图中的「方法区」和 「堆」两部分。收集日志也基本上是描述这两部分的大小和变化情况。

在上面的背景介绍中给出了本次测试所用的参数。年轻代 10M ,老年代 10M,Metaspace 区 6M。下图是堆空间内存分布图,年轻代分为 Eden区和 S0、S1 两个区,_SurvivorRatio_为8,这也是默认值,表示新生代 Eden 占年轻代总大小的 80%,也就是 10*80%=8M,而 S0、S1 各占10%,也就是 1M。

好了,基于上面的基础认识。开始分析垃圾收集日志,以下是两条日志,第一条是一次 Minor GC,第二条是 Full GC。

2019-12-03T16:20:47.980-0800: [GC (System.gc()) [PSYoungGen: 4068K->656K(9216K)] 4076K->672K(19456K), 0.0016106 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

2019-12-03T16:20:47.982-0800: [Full GC (System.gc())

[PSYoungGen: 656K->0K(9216K)],

[ParOldGen: 16K->570K(10240K)] 672K->570K(19456K),

[Metaspace: 3910K->3910K(1056768K)],

0.0110117 secs]

[Times: user=0.02 sys=0.00, real=0.01 secs]

为了更清楚的说明各个部分的含义,我居然又画了一张图(PS:画个图真是不容易),看一下各部分代表的含义。

上图标注的是一条 Full GC 日志,Full GC 同时收集了年轻代、老年代以及 metaspace 区。Full GC 日志包含了 Minor GC 的内容,那我们就直接分析 Full GC 了。

时间戳:日志以时间戳作为开端,表示此次垃圾收集发生的时间,由 -XX:+PrintGCDateStamps 参数决定是否开启。

收集内容主体:

沿着日志顺序往后看,Full GC (System.gc()),收集类型(是 Full GC 还是 Minor GC) ,括号里跟着发生此次垃圾收集的原因。

再后面是年轻代、老年代、Metaspace 区详细的收集情况。

[PSYoungGen: 656K->0K(9216K)],翻译为 「年轻代:年轻代收集前内存使用量->年轻代垃圾收集后内存使用量(年轻代可用内存总大小)」,垃圾收集前年轻代已使用 656K,垃圾收集后已使用 0K,说明被回收了 656K,总可用大小为 9216K(9M)。诶,不对呀?怎么是 9M 呢,年轻代不是分了 10 M 吗。因为可用内存和总内存不能划等号,S0 和 S1 只能有一块被算进可用内存,所以可用内存为 Eden + S0/S1=9M。

[ParOldGen: 16K->570K(10240K)] 672K->570K(19456K),翻译为 「[老年代:老年代收集前内存使用量->老年代垃圾收集后内存使用量(老年代可用内存总大小)] 堆空间(包括年轻代和老年代)垃圾收集前内存使用量->堆空间垃圾收集后内存使用量(堆空间总可用大小)」。

垃圾收集前老年使用 16K,收集后呢,竟然变大了,确定没有看错吗。是的,没有。这是因为年轻代的对象有一些进入了老年代导致的。老年代 16K 变成了 570K,说明有 554K 是年轻代晋升而来的。而内存总大小由 672K 减少到了 570K,说明有102K的内存真正的被清理了。

[Metaspace: 3910K->3910K(1056768K)]翻译为元空间回收前大小为 3910K,回收后大小为3910K,总可用大小为 1056768K。我们不是设置的 6M 吗,怎么这么大,没起作用吗。实际上这个值是 *_CompressedClassSpaceSize +(2_InitialBootClassLoaderMetaspaceSize) **的大小,我们只设置了 MaxMetaspaceSize ,并没有设置这两个参数。使用如下命令可以看到这两个值的默认大小

jinfo -flag CompressedClassSpaceSize 75867

-XX:CompressedClassSpaceSize=1073741824

jinfo -flag InitialBootClassLoaderMetaspaceSize 75867

-XX:InitialBootClassLoaderMetaspaceSize=4194304

单位是 byte,CompressedClassSpaceSize 的值是 1048576K(其实就是1G,默认值),InitialBootClassLoaderMetaspaceSize的值是 4M,用上面的公式计算,正好是 1056768K(1032M)

耗时统计

[Times: user=0.02 sys=0.00, real=0.01 secs]

user=0.02 表示执行用户态代码的耗时,这里也就是 GC 线程消耗的 CPU 时间。如果是多线程收集器,这个值会高于 real 时间。

sys=0.00 表示执行内核态代码的耗时。

real=0.01 表示应用停顿时长,多线程垃圾收集情况下,此数值应该接近(user + sys) / GCThreads(收集线程数),即单核上的平均停顿时间。

CMS 收集器

CMS 是一款老年代垃圾收集器,年轻代使用 ParNew 与之配合使用。它是一款并发、低停顿的垃圾收集器。适用于要求低延迟、即时响应的应用系统。

CMS 规划的内存模型和上面 Parallel Scavenge 的是一致的,可以参考上面的内存分布图。

CMS 采用标记-清除算法,算法过程比较复杂,分为一下几个步骤:

  • 初始标记(CMS initial mark),会导致 stop the world;

  • 并发标记(CMS concurrent mark),与用户线程同时运行;

  • 预清理(CMS-concurrent-preclean),与用户线程同时运行;

  • 可被终止的预清理(CMS-concurrent-abortable-preclean) 与用户线程同时运行;

  • 重新标记(CMS remark),会导致 stop the world;

  • 并发清除(CMS concurrent sweep),与用户线程同时运行;

  • 并发重置状态等待下次CMS的触发(CMS-concurrent-reset),与用户线程同时运行;

只有初始标记和重新标记这两个步骤会导致 STW,但是这两个步骤耗时很短,其他步骤可以与用户线程同时运行,所以用户几乎感觉不到 JVM 停顿。

使用参数 -XX:+UseConcMarkSweepGC可启用 CMS 垃圾收集器。更详细的参数如下:

-XX:+UseConcMarkSweepGC

-XX:CMSInitiatingOccupancyFraction=70

-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses

-XX:+CMSClassUnloadingEnabled

-XX:+ParallelRefProcEnabled

在重新标记之前对年轻代做一次minor GC

-XX:+CMSScavengeBeforeRemark

使用了-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses或-XX:+ExplicitGCInvokesConcurrent参数,在进行 Full GC 的时候,比如执行 System.gc() 操作,会触发 CMS GC,以此来提高 GC 效率。

以下是启用 CMS 后摘的一段 GC 日志,由于内容过长,下面我就直接在日志上做注释了。

System.gc() 触发一次 Full GC -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses 参数 导致Full GC 以 CMS GC 方式执行 先由 ParNew 收集器回收年轻代

2019-12-03T16:43:03.179-0800: [GC (System.gc()) 2019-12-03T16:43:03.179-0800: [ParNew: 3988K->267K(9216K), 0.0091869 secs] 3988K->919K(19456K), 0.0092257 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

初始标记阶段,标记那些直接被 GC root 引用或者被年轻代存活对象所引用的所有对象 老年代当前使用 651K 老年代可用大小 10240K=10M 当前堆内存使用量 91 《一线大厂Java面试题解析+后端开发学习笔记+最新架构讲解视频+实战项目源码讲义》开源 9K 当前堆可用内存 19456K=19M “1 CMS-initial-mark” 这里的 1 表示老生代

2019-12-03T16:43:03.189-0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 651K(10240K)] 919K(19456K), 0.0002156 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

并发标记开始 标记所有存活的对象,它会根据上个阶段找到的 GC Roots 遍历查找

2019-12-03T16:43:03.189-0800: [CMS-concurrent-mark-start]

并发标记阶段耗时统计

2019-12-03T16:43:03.190-0800: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

并发预清理阶段开始 在上述并发标记过程中,一些对象的引用可能会发生变化,JVM 会将包含这个对象的区域(Card)标记为 Dirty 在此阶段,能够从 Dirty 对象到达的对象也会被标记,这个标记做完之后,dirty card 标记就会被清除了

2019-12-03T16:43:03.190-0800: [CMS-concurrent-preclean-start]

最后总结我的面试经验

2021年的金三银四一眨眼就到了,对于很多人来说是跳槽的好机会,大厂面试远没有我们想的那么困难,摆好心态,做好准备,你也可以的。

另外,面试中遇到不会的问题不妨尝试讲讲自己的思路,因为有些问题不是考察我们的编程能力,而是逻辑思维表达能力;最后平时要进行自我分析与评价,做好职业规划,不断摸索,提高自己的编程能力和抽象思维能力。

BAT面试经验

实战系列:Spring全家桶+Redis等

其他相关的电子书:源码+调优

面试真题:


,摆好心态,做好准备,你也可以的。

另外,面试中遇到不会的问题不妨尝试讲讲自己的思路,因为有些问题不是考察我们的编程能力,而是逻辑思维表达能力;最后平时要进行自我分析与评价,做好职业规划,不断摸索,提高自己的编程能力和抽象思维能力。

[外链图片转存中…(img-0KScaVJk-1650525676181)]

BAT面试经验

实战系列:Spring全家桶+Redis等

[外链图片转存中…(img-VywiI6XS-1650525676181)]

其他相关的电子书:源码+调优

[外链图片转存中…(img-yc49tese-1650525676182)]

面试真题:

[外链图片转存中…(img-yPwDZ9ZS-1650525676182)]

[外链图片转存中…(img-D6ihhn2t-1650525676183)]

转载请注明:文章转载自 www.mshxw.com
本文地址:https://www.mshxw.com/it/826852.html
我们一直用心在做
关于我们 文章归档 网站地图 联系我们

版权所有 (c)2021-2022 MSHXW.COM

ICP备案号:晋ICP备2021003244-6号