0
点赞
收藏
分享

微信扫一扫

手撕 JVM 垃圾收集日志,synchronized底层是怎么实现的

云岭逸人 2022-04-22 阅读 79

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

2019-12-03T16:20:47.980-0800: [GC (System.gc()) [PSYoungGen: 4068K->656K(9216K)] 4076K->672K Java开源项目【ali1024.coding.net/public/P7/Java/git】 (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:画个图真是不容易),看一下各部分代表的含义。

11561958-b28b10cb2980bc27.png

上图标注的是一条 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

当前堆内存使用量 919K

当前堆可用内存 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.0 《一线大厂Java面试题解析+后端开发学习笔记+最新架构讲解视频+实战项目源码讲义》开源 0, 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]

并发预清理耗时统计

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

重新标记阶段,目的是完成老年代中所有存活对象的标记

上一阶段是并发执行的,在执行过程中对象的引用关系还会发生变化,所以再次标记

因为配置了 -XX:+CMSScavengeBeforeRemark 参数,所以会在标记发生一次 Minor GC

进行一次Minor GC,完成后年轻代可用空间 267K,年轻代总大小9216K

2019-12-03T16:43:03.190-0800: [GC (CMS Final Remark) [YG occupancy: 267 K (9216 K)]

更详细的年轻代收集情况

2019-12-03T16:43:03.190-0800: [GC (CMS Final Remark) 2019-12-03T16:43:03.190-0800: [ParNew: 267K->103K(9216K), 0.0021800 secs] 919K->755K(19456K), 0.0022127 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

在程序暂停时重新进行扫描(Rescan),以完成存活对象的标记

2019-12-03T16:43:03.192-0800: [Rescan (parallel) , 0.0002866 secs]

第一子阶段:处理弱引用

2019-12-03T16:43:03.193-0800: [weak refs processing, 0.0015605 secs]

第二子阶段:卸载不适用的类

2019-12-03T16:43:03.194-0800: [class unloading, 0.0010847 secs]

第三子阶段:清理持有class级别 metadata 的符号表(symbol tables),以及内部化字符串对应的 string tables

完成后老年代使用量为651K(老年代总大小10240K=10M)

整个堆使用量 755K(总堆大小19456K=19M)

2019-12-03T16:43:03.195-0800: [scrub symbol table, 0.0015690 secs]

2019-12-03T16:43:03.197-0800: [scrub string table, 0.0003786 secs][1 CMS-remark: 651K(10240K)] 755K(19456K), 0.0075058 secs] [Times: user=0.01 sys=0.01, real=0.00 secs]

#开始并发清理 清除未被标记、不再使用的对象以释放内存空间

2019-12-03T16:43:03.198-0800: [CMS-concurrent-sweep-start]

#并发清理阶段耗时

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

开始并发重置,重置CMS算法相关的内部数据, 为下一次GC循环做准备

2019-12-03T16:43:03.198-0800: [CMS-concurrent-reset-start]

重置耗时

2019-12-03T16:43:03.199-0800: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

下面是执行 jmap -histo:live 命令触发的 Full GC

GC 类型是 Full GC

触发原因是 Heap Inspection Initiated GC

CMS收集老年代:从清理前的650K变为清理后的617K,总的老年代10M,耗时0.0048490秒

总堆使用大小由 1245K变为617K,总堆19M

metaspace: 3912K变为3912K,

metaspace 总大小显示为 CompressedClassSpaceSize +(2*InitialBootClassLoaderMetaspaceSize)

2019-12-03T16:43:20.115-0800: [Full GC (Heap Inspection Initiated GC) 2019-12-03T16:43:20.115-0800: [CMS: 650K->617K(10240K), 0.0048490 secs] 1245K->617K(19456K), [Metaspace: 3912K->3912K(1056768K)], 0.0049050 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

以上就是对 CMS 垃圾收集器产生日志的分析,因为过程复杂,所以产生的日志内容也比较多。

G1 收集器

G1 收集器是在 JDK 7 版本中就已经正式推出,并且作为 JDK 9 默认的垃圾收集器。

Parallel Scavenge:我追求高吞吐量,现在社会什么最重要,效率呀,有没有。

CMS:效率固然重要,极致的用户体验才是王道啊,不能让用户等啊,不能等啊,低停顿、即时响应是我毕生追求。

G1(一脸不屑):有句话不只当讲不当讲,首先声明没有恶意,我想说,在座的各位都是垃圾。上面两位说的,我全都有,是的,全都有。 (ps:结果被打)

以上纯属开个玩笑,只是为了说明 G1 在满足了低停顿的同时也保证了高吞吐量,适用于多核处理器、大内存容量的服务端系统。

G1 是 CMS 的替代版本,具有如下特点:

  • 横跨年轻代和老年代,不需要其他收集器配合;

  • 并发收集器,可以与用户线程并发执行;

  • 会压缩内存碎片;

  • 可预测的停顿时间与高吞吐量;

与其他的垃圾收集器不同,G1 对堆内存做了不一样的规划,虽然还是使用分代策略,分为老年代、年轻代,年轻代又分为 Eden、Survivior 区,但是只是逻辑划分,物理上并不连续。它是将堆内存分为一系列大小在1M-32M 不等的 Region 区,通过下方的图可以直观的看出效果。

11561958-6aa1df7b04fbf05c.png

最后

权威指南-第一本Docker书

引领完成Docker的安装、部署、管理和扩展,让其经历从测试到生产的整个开发生命周期,深入了解Docker适用于什么场景。并且这本Docker的学习权威指南介绍了其组件的基础知识,然后用Docker构建容器和服务来完成各种任务:利用Docker为新项目建立测试环境,演示如何使用持续集成的工作流集成Docker,如何构建应用程序服务和平台,如何使用Docker的API,如何扩展Docker。

总共包含了:简介、安装Docker、Docker入门、使用Docker镜像和仓库、在测试中使用Docker、使用Docker构建服务、使用Fig编配Docke、使用Docker API、获得帮助和对Docker进行改进等9个章节的知识。

image

image

image

image

关于阿里内部都在强烈推荐使用的“K8S+Docker学习指南”—《深入浅出Kubernetes:理论+实战》、《权威指南-第一本Docker书》,看完之后两个字形容,爱了爱了!
er的API,如何扩展Docker。

总共包含了:简介、安装Docker、Docker入门、使用Docker镜像和仓库、在测试中使用Docker、使用Docker构建服务、使用Fig编配Docke、使用Docker API、获得帮助和对Docker进行改进等9个章节的知识。

[外链图片转存中…(img-XWmLi57G-1650624944180)]

[外链图片转存中…(img-hIU0L9tZ-1650624944180)]

[外链图片转存中…(img-fd2b2AuN-1650624944181)]

[外链图片转存中…(img-LBdcZgV4-1650624944181)]

关于阿里内部都在强烈推荐使用的“K8S+Docker学习指南”—《深入浅出Kubernetes:理论+实战》、《权威指南-第一本Docker书》,看完之后两个字形容,爱了爱了!

举报

相关推荐

0 条评论