系统压测FullGC日志分析

应用背景分析

压测一个业务系统，其中JVM堆内存参数如下，堆内存设置了6g，新生代3g，老年代相应的为3g，采用了CMS垃圾回收器，新生代则默认为ParNew回收器，设定触发FullGC规则为老年代使用率达到70%（默认值为75%），调低该值的目的在于降低内存碎片的影响，希望更早的触发垃圾回收。CMS垃圾回收时会采用标记清除算法，同时默认会在清除以后执行整理压缩，避免浮动垃圾与内存碎片。

 -Xms6144M -Xmx6144M -Xmn3072M -XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:LargePageSizeInBytes=128m -XX:+UseFastAccessorMethods -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=70 -XX:+PrintGCDetails -XX:+PrintGCDateStamps -verbose:gc -Xloggc:/wls/springboot/logs/gc.log -Djava.net.preferIPv4Stack=true

设定了如上的JVM参数下开始进行压测，现在分析一波基于CMS的FullGC日志。

Phase 1: Initial Mark 初始标记

---

该阶段会STW现象，这是CMS中两次stop-the-world事件中的一次。它有两个目标：一是标记老年代中所有的GC Roots；二是标记被年轻代中活着的对象引用的对象。

2020-04-28T16:09:39.160+0800: 1108.793: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2204173K(3145728K)] 2370012K(5976896K), 0.0514097 secs] [Times
: user=0.13 sys=0.04, real=0.05 secs] 

从以上日志信息中可以提取到如下信息：

• 老年代容量3g，当前使用2.1g
• 整个堆容量5.7g，当前使用2.26g
• 耗时0.0514097s

Phase 2: Concurrent Mark 并发标记

---

这个阶段不会STW，JVM会遍历整个老年代并且标记所有存活的对象，从“初始化标记”阶段找到的GC Roots开始。并发标记的特点是和应用程序线程同时运行，并不是老年代的所有存活对象都会被标记，因为标记的同时应用程序会改变一些对象的引用等。截取GC日志如下：

2020-04-28T16:09:39.213+0800: 1108.845: [CMS-concurrent-mark-start]
2020-04-28T16:09:39.490+0800: 1109.123: [CMS-concurrent-mark: 0.278/0.278 secs] [Times: user=1.09 sys=0.46, real=0.28 secs] 

其中，0.278/0.278 secs就是展示该阶段持续的时间和时钟时间；

Phase 3: Final Remark 重新标记

---

此处可以细分三个小阶段，只有第三个Final Remark阶段会有STW。

1、Concurrent Preclean

这里仍是一个回收线程并发执行阶段，和应用线程并行运行。前一个阶段在并行运行的时候，一些对象的引用已经发生了变化，当这些引用发生变化的时候，JVM会标记堆的这个区域为Dirty Card(包含被标记但是改变了的对象，被认为"dirty")，这就是 Card Marking。

2020-04-28T16:09:39.491+0800: 1109.124: [CMS-concurrent-preclean-start]
2020-04-28T16:09:39.558+0800: 1109.191: [CMS-concurrent-preclean: 0.067/0.067 secs] [Times: user=0.15 sys=0.07, real=0.07 secs] 

2、Concurrent Abortable Preclean

又一个并发阶段不会停止应用程序线程。这个阶段尝试着去承担STW的Final Remark阶段足够多的工作。这个阶段持续的时间依赖好多的因素，由于这个阶段是重复的做相同的事情直到发生aboart的条件（比如：重复的次数、多少量的工作、持续的时间等等）之一才会停止。

2020-04-28T16:09:39.559+0800: 1109.192: [CMS-concurrent-abortable-preclean-start]
2020-04-28T16:09:40.812+0800: 1110.445: [GC (Allocation Failure) 2020-04-28T16:09:40.813+0800: 1110.445: [ParNew: 2567678K->51415K(2831168K), 0.15
12751 secs] 4771852K->2259993K(5976896K), 0.1521682 secs] [Times: user=0.85 sys=0.03, real=0.16 secs] 
2020-04-28T16:09:41.753+0800: 1111.386: [CMS-concurrent-abortable-preclean: 2.030/2.194 secs] [Times: user=7.99 sys=2.63, real=2.20 secs] 

这个阶段很大程度的影响着即将来临的Final Remark的停顿

3、Final Remark

清理前做最终的标记，这个阶段是CMS中第二个并且是最后一个STW的阶段。该阶段的任务是完成标记整个年老代的所有的存活对象。由于之前的预处理是并发的，它可能跟不上应用程序改变的速度，这个时候，STW是非常需要的来完成这个严酷考验的阶段。通常CMS尽量运行Final Remark阶段在年轻代是足够干净的时候，目的是消除紧接着的连续的几个STW阶段。

2020-04-28T16:09:41.757+0800: 1111.390: [GC (CMS Final Remark) [YG occupancy: 1451165 K (2831168 K)]
2020-04-28T16:09:41.757+0800: 1111.390: [Rescan (parallel) , 0.2057074 secs]
2020-04-28T16:09:41.963+0800: 1111.595: [weak refs processing, 0.0000816 secs]
2020-04-28T16:09:41.963+0800: 1111.596: [class unloading, 0.1070335 secs]
2020-04-28T16:09:42.070+0800: 1111.703: [scrub symbol table, 0.0133941 secs]
2020-04-28T16:09:42.083+0800: 1111.716: [scrub string table, 0.0012260 secs][1 CMS-remark: 2208578K(3145728K)] 3659743K(5976896K), 0.3312628 secs] [Times: user=1.28 sys=0.01, real=0
.33 secs]

• CMS Final Remark – 收集阶段，这个阶段会标记老年代全部的存活对象，包括那些在并发标记阶段更改的或者新创建的引用对象；YG occupancy: 1451165 K (2831168 K) – 年轻代当前占用情况(1.38g)和容量(2.7g)；
• [Rescan (parallel) , 0.0085125 secs] – 这个阶段在应用停止的阶段完成存活对象的标记工作；
• weak refs processing,处理弱引用
• class unloading 卸载类
• scrub symbol table 清理符号对象
• scrub string table 清理字符串常量对象

通过以上5个阶段的标记，老年代所有存活的对象已经被标记并且现在要通过Garbage Collector采用清扫的方式回收那些不能用的对象了。

Phase 4: 垃圾回收

---

这个阶段可以划分两个小阶段，这两个都不会STW。

1、Concurrent Sweep

这个阶段的目的就是移除那些不用的对象，回收他们占用的空间并且为将来使用。

2020-04-28T16:09:43.698+0800: 1113.331: [CMS-concurrent-sweep: 1.579/1.609 secs] [Times: user=5.35 sys=2.34, real=1.61 secs] 

2、Concurrent Reset

这个阶段并发执行，重新设置CMS算法内部的数据结构，准备下一个CMS生命周期的使用。

2020-04-28T16:09:43.699+0800: 1113.332: [CMS-concurrent-reset-start]
2020-04-28T16:09:43.707+0800: 1113.339: [CMS-concurrent-reset: 0.008/0.008 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]

0.008/0.008 secs为该阶段的持续时间。

总结

---

总体来看，FGC的时长大约在4s，其中STW的时长为0.27+0.20+0.1+0.33=0.81s。FGC的回收时长较大，原因在于JVM堆内存的空间较大，导致在多个标记阶段耗时较长，且FGC期间因为会开启多线程进行并发回收，会出现CPU使用率上的毛刺现象，但是整体来看STW上的0.81s满足CMS一贯的低延时优点，如果在生产上内存*2的情况下，FGC和STW时长可能会线性倍增两倍。如果观察线上FGC时长过大，CPU使用率因FGC出现较多毛刺的情况下，说明CMS在应对大内存服务的回收时会显得力不从心，可以考虑采用G1回收器对JVM进行调优处理。

以下展示为CMS的完整GC日志与时间，可供大家学习参考。

2020-04-28T16:09:39.160+0800: 1108.793: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2204173K(3145728K)] 2370012K(5976896K), 0.0514097 secs] [Times
: user=0.13 sys=0.04, real=0.05 secs] 

2020-04-28T16:09:39.213+0800: 1108.845: [CMS-concurrent-mark-start]
2020-04-28T16:09:39.490+0800: 1109.123: [CMS-concurrent-mark: 0.278/0.278 secs] [Times: user=1.09 sys=0.46, real=0.28 secs] 

2020-04-28T16:09:39.491+0800: 1109.124: [CMS-concurrent-preclean-start]
2020-04-28T16:09:39.558+0800: 1109.191: [CMS-concurrent-preclean: 0.067/0.067 secs] [Times: user=0.15 sys=0.07, real=0.07 secs] 

2020-04-28T16:09:39.559+0800: 1109.192: [CMS-concurrent-abortable-preclean-start]
2020-04-28T16:09:40.812+0800: 1110.445: [GC (Allocation Failure) 2020-04-28T16:09:40.813+0800: 1110.445: [ParNew: 2567678K->51415K(2831168K), 0.15
12751 secs] 4771852K->2259993K(5976896K), 0.1521682 secs] [Times: user=0.85 sys=0.03, real=0.16 secs] 
2020-04-28T16:09:41.753+0800: 1111.386: [CMS-concurrent-abortable-preclean: 2.030/2.194 secs] [Times: user=7.99 sys=2.63, real=2.20 secs] 

2020-04-28T16:09:41.757+0800: 1111.390: [GC (CMS Final Remark) [YG occupancy: 1451165 K (2831168 K)]2020-04-28T16:09:41.757+0800: 1111.390: [Resca
n (parallel) , 0.2057074 secs]2020-04-28T16:09:41.963+0800: 1111.595: [weak refs processing, 0.0000816 secs]2020-04-28T16:09:41.963+0800: 1111.596
: [class unloading, 0.1070335 secs]2020-04-28T16:09:42.070+0800: 1111.703: [scrub symbol table, 0.0133941 secs]2020-04-28T16:09:42.083+0800: 1111.
716: [scrub string table, 0.0012260 secs][1 CMS-remark: 2208578K(3145728K)] 3659743K(5976896K), 0.3312628 secs] [Times: user=1.28 sys=0.01, real=0
.33 secs] 
2020-04-28T16:09:42.089+0800: 1111.722: [CMS-concurrent-sweep-start]
2020-04-28T16:09:42.778+0800: 1112.411: [GC (Allocation Failure) 2020-04-28T16:09:42.778+0800: 1112.411: [ParNew: 2567977K->56794K(2831168K), 0.01
90506 secs] 3999542K->1491602K(5976896K), 0.0197083 secs] [Times: user=0.24 sys=0.01, real=0.02 secs] 
2020-04-28T16:09:43.698+0800: 1113.331: [CMS-concurrent-sweep: 1.579/1.609 secs] [Times: user=5.35 sys=2.34, real=1.61 secs] 
2020-04-28T16:09:43.699+0800: 1113.332: [CMS-concurrent-reset-start]
2020-04-28T16:09:43.707+0800: 1113.339: [CMS-concurrent-reset: 0.008/0.008 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]