系统压测的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.1512751 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.1512751 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: [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]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.0190506 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]