JVM-GC日志分析

[TOC]

1.前言

有时候会因为应用的线上机器发生 OGC 而收到告警电话的轰炸和来自各个上层业务方的调用超时反馈。每次发生GC的时候很少对这一次OGC的过程做了哪些事情进行一次摸底的分析。仅仅是从dump下来的堆文件排查问题点在哪然后具体优化掉，而缺少问为什么GC会这么久？。于是周末借着杭州的绵绵春雨不能出门浪，祭出了前不久找运维老哥拉的一份线上机器的GC日志，结合 garbage-collection-algorithms-implementations 对自己应用的GC日志进行一次摸底的学习记录。
先介绍下，笔者的应用是一个比较早的也是比较核心的底层应用，使用 ParNew + CMS 的收集器组合,开启了如下JVM参数:

-XX:+UseParNewGC         // 使用ParNewGC作为新生代收集器
-XX:+UseConcMarkSweepGC   // 使用CMSGC作为老年代收集器
-XX:+PrintGCDetails       // 发生GC时打印日志
-XX:GCLogFileSize=100M    // GC日志的最大长度
-Xloggc:/data/logs/gc.log     // GC日志的存放位置
-XX:PrintFLSStatistics=2   // 该参数可以协助观察碎片问题

2. 新生代日志分析

ParNew 是优秀的新生代常见的收集器，采用的是复制算法对新生代内容进行收集。具体不做过多介绍，网上文章和神书《深入理解JVM虚拟机》中有很详细的介绍。

2.1 ParNew GC log

先来一段真实机器的 ParNew GC 日志

2020-03-23T22:47:43.826+0800: 303036.198: [ParNew: 2242195K->5973K(2515968K), 0.0135848 secs] 2539280K->303190K(5313536K)After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 238113288
Max   Chunk Size: 178875799
Number of Blocks: 14986
Av.  Block  Size: 15889
Tree      Height: 28
Statistics for IndexedFreeLists:
--------------------------------
Total Free Space: 81915187
Max   Chunk Size: 256
Number of Blocks: 19097485
Av.  Block  Size: 4
free=320028475 frag=0.6876
, 0.0154776 secs] [Times: user=0.04 sys=0.02, real=0.02 secs] 

ParNew GC

为了方便分析,分别在各处位置上做了标注方便分析查看，下面具体解释每处日志所记载的含义(未标注颜色的部分,是开启了-XX:PrintFLSStatistics=2这个分析碎片的参数才有的日志,后面介绍这个参数时单独分析):

• 2020-03-23T22:47:43.826+0800: 标识本次GC的发生时间
• 303036.198: 标识本次GC时,JVM运行了多久,单位是秒
• ParNew: 标识本次GC的类型是 ParNew GC,发生在新生代
• 2242195K->5973K(2515968K): 本次GC前新生代的容量为 2242195K,收集后新生代的容量为5973K,新生代的总大小为 2515968K
• 0.0135848 secs : 垃圾收集器在 w/o final cleanup 阶段消耗的时间
• 2539280K->303190K(5313536K): 本次GC前后,整个堆的变化情况
• 0.0154776 secs:ParNew 收集器标记和复制年轻代活着的对象所花费的时间（包括和老年代通信的开销、对象晋升到老年代开销、垃圾收集周期结束一些最后的清理对象等的花销）
• [Times: user=0.95 sys=0.00, real=0.09 secs]:
  • user: Total CPU time that was consumed by the garbage collector threads during this collection, 翻译就是在此次垃圾回收过程中,由GC线程所消耗的总的CPU时间
  • sys: Time spent in OS calls or waiting for system event. GC过程中中操作系统调用和系统等待事件所消耗的时间
  • real: 应用程序暂停的时间,在ParNew收集器中,这个值约等于 (user + sys)/GC线程数

2.2 PrintFLSStatistics=2 gc log

在对象的创建过程中, 当类加载检查通过后，接下来虚拟机将为新生对象分配内存。对象所需的内存大小在类加载完成后便可确定，为对象分配空间的任务等同于把一块确定大小的内存从Java堆中划分出来。分配方式有 指针碰撞 和 空闲列表 两种，选择那种分配方式由Java堆是否规整决定，而Java堆是否规整又由所采用的垃圾收集器是否带有压缩整理功能决定。所以类似Serial、ParNew 等收集器时采用指针碰撞，而采用CMS这种基于Mark-Sweep算法的收集器时采用空闲列表。

当 BinaryTreeDictionary > 0时,会打印BinaryTreeDictionary统计信息, 当 BinaryTreeDictionary > 1 时,会打印IndexedFreeLists信息,我们分别分析上述的这2个信息。

• BinaryTreeDictionary:输出统计字典信息
  • Total Free Space: 238113288:剩余空闲容量约238M
  • Max Chunk Size: 178875799:最大的块容量为178M
  • Number of Blocks: 14986:一共有14986个块(chunk)
  • Av. Block Size: 15889:平均每个块的大小为0.015M(平均 * 一共多少块 = 剩余空闲块容量)
  • Tree Height: 28:碎片的高度 28。(这个碎片的高度只查到了这个值越大代表碎片情况越严重,初始值为0，这里先mark下)
• IndexedFreeLists free list(空闲列表)的统计信息
  • free=320028475: 空闲空间的长度
  • frag=0.6876: 碎片率,初始值为0.0000,代表刚开始没有内存碎片,值越高代表碎片越严重,这里就很明显了 68.76%的内存碎片

3. 老年代日志分析

CMS 是一种以获取最短回收停顿时间为目标的收集器，也是现在比较常见的收集器之一，表现也是非常不多的，作用于老年代，基于 标记-清除 算法实现。

3.1 CMS log

上面所介绍的是新生代的收集器 ParNew 在GC的时候的日志,其它类型的收集器日志类似。这部分看一下当 CMS 收集器 GC 的时候的一些日志

2020-03-23T20:18:19.053+0800: 294071.426: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1398935K(2797568K)] 1406639K(5313536K), 0.0072307 secs] [Times: user=0.01 sys=0.02, real=0.01 secs] 
2020-03-23T20:18:19.061+0800: 294071.434: [CMS-concurrent-mark-start]
2020-03-23T20:18:19.220+0800: 294071.592: [CMS-concurrent-mark: 0.159/0.159 secs] [Times: user=0.19 sys=0.15, real=0.16 secs] 
2020-03-23T20:18:19.220+0800: 294071.593: [CMS-concurrent-preclean-start]
2020-03-23T20:18:19.232+0800: 294071.604: [CMS-concurrent-preclean: 0.011/0.012 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
2020-03-23T20:18:19.232+0800: 294071.605: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2020-03-23T20:18:24.248+0800: 294076.621: [CMS-concurrent-abortable-preclean: 4.982/5.016 secs] [Times: user=8.69 sys=1.17, real=5.02 secs] 
2020-03-23T20:18:24.252+0800: 294076.625: [GC (CMS Final Remark) [YG occupancy: 981108 K (2515968 K)]
2020-03-23T20:18:24.252+0800: 294076.625: [Rescan (parallel) , 0.1437009 secs]
2020-03-23T20:18:24.396+0800: 294076.769: [weak refs processing, 0.1088229 secs]
2020-03-23T20:18:24.505+0800: 294076.878: [class unloading, 0.0627101 secs]
2020-03-23T20:18:24.568+0800: 294076.940: [scrub symbol table, 0.0237866 secs]
2020-03-23T20:18:24.592+0800: 294076.964: [scrub string table, 0.0027650 secs][1 CMS-remark: 1398935K(2797568K)] 2380043K(5313536K), 0.3741943 secs] [Times: user=0.81 sys=0.00, real=0.37 secs] 
2020-03-23T20:18:24.627+0800: 294077.000: [CMS-concurrent-sweep-start]
2020-03-23T20:18:29.120+0800: 294081.493: [CMS-concurrent-sweep: 2.079/4.493 secs] [Times: user=10.39 sys=0.95, real=4.49 secs] 
2020-03-23T20:18:29.121+0800: 294081.493: [CMS-concurrent-reset-start]
2020-03-23T20:18:29.134+0800: 294081.507: [CMS-concurrent-reset: 0.013/0.013 secs] [Times: user=0.01 sys=0.02, real=0.01 secs] 

下面分别从 CMS 工作的过程分析上面这部分 CMS GC 的日志

1. CMS Initial Mark: 初始标记,它是CMS的STW发生的2个阶段其中的一个,标记那些直接被 GC root 引用或者被年轻代存活对象所引用的所有对象，下发图片均引用自 plumbr.io。
   • 1398935K:当前老年代使用的容量
   • 2797568K:老年代最大容量
   • 1406639K:整个堆使用的容量
   • 5313536K:整个堆的容量
   • 0.0072307 secs:这个阶段持续了的时间

2020-03-23T20:18:19.053+0800: 294071.426: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1398935K(2797568K)] 1406639K(5313536K), 0.0072307 secs] [Times: user=0.01 sys=0.02, real=0.01 secs] 

Initial Mark

2. CMS-concurrent-mark-start:并发标记,此阶段会遍历老年代,标记所有存活的对象,这个阶段是和用户线程并发工作的,并不能标记所有的老年代存户对象,因为刚刚说了它是和用户线程并发工作的,在它标记期间,用户线程可能还会改变一些引用关系,日志如下,可类比上方的分析,此处不做重复介绍

2020-03-23T20:18:19.061+0800: 294071.434: [CMS-concurrent-mark-start]
2020-03-23T20:18:19.220+0800: 294071.592: [CMS-concurrent-mark: 0.159/0.159 secs] [Times: user=0.19 sys=0.15, real=0.16 secs] 

concurrent-mark

3. CMS-Concurrent Preclean:这也是个并发的过程,和用户线程同时工作,刚刚在2中说了,并发标记的过程中,因为是和用户线程共同工作,可能会修改引用关系,当有相关引用修改时,JVM将包含这个对象区域标记为脏的区域:Dirty 。说白了就是在并发标记中如果有对象的引用改变了就标记改变的对象。
   Concurrent Preclean

在pre-clean阶段，那些能够从 Dirty 对象到达的对象也会被标记，这个标记做完之后，Dirty标记就会被清除了。

pre-clean

2020-03-23T20:18:19.220+0800: 294071.593: [CMS-concurrent-preclean-start]
2020-03-23T20:18:19.232+0800: 294071.604: [CMS-concurrent-preclean: 0.011/0.012 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
2020-03-23T20:18:19.232+0800: 294071.605: [CMS-concurrent-abortable-preclean-start]

4. CMS-Concurrent Abortable Preclean: 这个阶段也是个并发阶段,它是为了尽量承担 下面阶段5最终标记的工作量,尽量少的减少 STW 的时长,这里的 gc 线程会在 STW 之前做更多的工作，通常会持续 5s 左右.也就是我们看到的 abort preclean due to time,可以发现,此时的时间 20:18:24,上一次日志的时间 20:18:19。

CMS: abort preclean due to time 2020-03-23T20:18:24.248+0800: 294076.621: [CMS-concurrent-abortable-preclean: 4.982/5.016 secs] [Times: user=8.69 sys=1.17, real=5.02 secs] 

5. CMS Final Remark:,最终标记,这是 第二个会导致 STW 的阶段,这个阶段的目标是标记所有老年代所有的存活对象，由于之前的阶段是并发执行的，gc 线程可能跟不上应用程序的变化，为了完成标记老年代所有存活对象的目标，STW 就非常有必要了，这也是最后一个 STW 的阶段，通常 CMS Final Remark 都尽量在年轻代比较空的时候运行，因为年轻代对象如果多的话，老年代对象被持有引用的概率就会相对较高,日志如下:
   • YG occupancy: 981108 K (2515968 K):年轻代当前容量和年轻代总容量
   • [Rescan (parallel) , 0.1437009 secs]:当应用暂停的情况下完成对所有存活对象的标记所使用的的时间，这个阶段是并行处理的
   • [weak refs processing, 0.1088229 secs]:弱引用的处理耗时,弱引用会在GC时被清理掉
   • [class unloading, 0.0627101 secs]:卸载不使用的类的耗时
   • [scrub symbol table, 0.0237866 secs]:擦除符号表的耗时
   • [scrub string table, 0.0027650 secs]:擦除字符串表的耗时
   • [1 CMS-remark: 1398935K(2797568K)] 2380043K(5313536K), 0.3741943 secs] [Times: user=0.81 sys=0.00, real=0.37 secs]:统计整个最终标记过程中的耗时以及标记情况信息

2020-03-23T20:18:24.252+0800: 294076.625: [GC (CMS Final Remark) [YG occupancy: 981108 K (2515968 K)]
2020-03-23T20:18:24.252+0800: 294076.625: [Rescan (parallel) , 0.1437009 secs]
2020-03-23T20:18:24.396+0800: 294076.769: [weak refs processing, 0.1088229 secs]
2020-03-23T20:18:24.505+0800: 294076.878: [class unloading, 0.0627101 secs]
2020-03-23T20:18:24.568+0800: 294076.940: [scrub symbol table, 0.0237866 secs]
2020-03-23T20:18:24.592+0800: 294076.964: [scrub string table, 0.0027650 secs][1 CMS-remark: 1398935K(2797568K)] 2380043K(5313536K), 0.3741943 secs] [Times: user=0.81 sys=0.00, real=0.37 secs] 

6. Concurrent Sweep:经历了上述的5个阶段,老年代的存活对象都已经标记完成了,到了这第6步,就是要完成的清理工作了。这个阶段不需要STW,可以和用户线程同时工作,在这一步主要是清除那些没有被标记的对象，回收它们的占用空间，日志比较简单不再进行重复分析。

2020-03-23T20:18:24.627+0800: 294077.000: [CMS-concurrent-sweep-start]
2020-03-23T20:18:29.120+0800: 294081.493: [CMS-concurrent-sweep: 2.079/4.493 secs] [Times: user=10.39 sys=0.95, real=4.49 secs] 

Concurrent Sweep

7. CMS-concurrent-reset:这个阶段也是并发执行的，它会重设 CMS 内部的数据结构，为下次的 GC 做准备

2020-03-23T20:18:29.121+0800: 294081.493: [CMS-concurrent-reset-start]
2020-03-23T20:18:29.134+0800: 294081.507: [CMS-concurrent-reset: 0.013/0.013 secs] [Times: user=0.01 sys=0.02, real=0.01 secs] 

3.2 CMS log 小结

CMS垃圾收集器通过将大量工作分散到不需要应用程序停止的并发线程上，在减少STW时间的方面做得很好，但是它也有一些弊端，比如:

1. CMS 无法处理 “浮动垃圾”，可能会出现 Concurrent Mode Failure 失败而导致另一次 Full GC 产生。CMS 并发清理时用户线程还运行着，程序运行就会有新的垃圾产生，这部分垃圾出现在标记过程之后，CMS无法在本次回收中回收他们，只好留到下次GC(这部分垃圾就叫浮动垃圾)。
2. CMS使用标记-清除算法，不会对内存进行整理，这可能会导致产生内存碎片，因为对象分配空间要求连续，大量的内存碎片会导致对象无法分配空间而触发FULL GC。-XX:+UseCMSCompactAtFullCollection 参数可以用来在FULL GC 的时候对内存碎片进行整理，但是会导致GC的停顿时间延长。
3. 如果我们的堆比较大的话，CMS面向要整理的空间就大，具体的GC时间难以预估，不像G1那样可以预估GC时间。

4. 总结

本文通过对线上应用的真实GC日志进行分析来学习GC日志相关的知识点，通过 ParNew GC 的日志了解了GC日志的一些结构，然后重点介绍了 CMS GC的过程，并且CMS的优缺点显而易见。通过 GC 日志的分析，更能准确的进一步给出调优JVM的一些依据和参考，也能印证调优前后的相关变化。

参照:
JAVA GARBAGE COLLECTION HANDBOOK