CMS收集过程和日志分析

发表于

本文根据线上jvm环境(Java 8)以及gc.log主要梳理ParNew GC和CMS GC执行过程

JVM参数

主要贴出相关一些参数：

1
2
3
4
5
6
7
8
9
10
11
-XX:MaxTenuringThreshold=8, 
-XX:ParallelGCThreads=8, 
-XX:+UseConcMarkSweepGC, 
-XX:+UseParNewGC, 
-XX:+DisableExplicitGC, 
-XX:+CMSParallelRemarkEnabled, 
-XX:+CMSClassUnloadingEnabled, 
-XX:CMSInitiatingOccupancyFraction=70, 
-XX:CMSFullGCsBeforeCompaction=5, 
-XX:+UseCMSCompactAtFullCollection, 
-XX:+CMSScavengeBeforeRemark,

ParNew and CMS

1
-XX:+UseParNewGC -XX:+UseConcMarkSweepGC

ParNew收集器是Serial收集器的多线程版本，作用于年轻代，采用多线程进行收集，但一样要STW；

345CMS的全称是Concurrent Mark and Sweep，作用于老年代，目标是最短停顿时间，我司绝大部分web服务采用ParNew + CMS(还有一些G1)

ParNew：采用 标记-复制 算法；

CMS：采用标记-清除 算法；

GC`日志

截取线上一段gc.log

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
// 
2019-03-21T11:19:41.609+0800: 1086345.976: [GC (Allocation Failure) 2019-03-21T11:19:41.609+0800: 1086345.976: [ParNew: 873168K->36622K(943744K), 0.0312849 secs] 3074543K->2238776K(4089472K), 0.0316707 secs] [Times: user=0.14 sys=0.00, real=0.04 secs] 
2019-03-21T11:19:41.643+0800: 1086346.010: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2202154K(3145728K)] 2238847K(4089472K), 0.0057407 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
2019-03-21T11:19:41.649+0800: 1086346.016: [CMS-concurrent-mark-start]
2019-03-21T11:19:41.915+0800: 1086346.282: [CMS-concurrent-mark: 0.266/0.266 secs] [Times: user=0.64 sys=0.01, real=0.27 secs] 
2019-03-21T11:19:41.915+0800: 1086346.282: [CMS-concurrent-preclean-start]
2019-03-21T11:19:41.968+0800: 1086346.335: [CMS-concurrent-preclean: 0.049/0.053 secs] [Times: user=0.06 sys=0.00, real=0.05 secs] 
2019-03-21T11:19:41.968+0800: 1086346.335: [CMS-concurrent-abortable-preclean-start]
2019-03-21T11:19:47.067+0800: 1086351.434: [CMS-concurrent-abortable-preclean: 4.876/5.099 secs] [Times: user=6.58 sys=0.02, real=5.10 secs] 
2019-03-21T11:19:47.069+0800: 1086351.436: [GC (CMS Final Remark) [YG occupancy: 51879 K (943744 K)]2019-03-21T11:19:47.069+0800: 1086351.436: [GC (CMS Final Remark) 2019-03-21T11:19:47.069+0800: 1086351.436: [ParNew: 51879K->23393K(943744K), 0.0156467 secs] 2254034K->2226423K(4089472K), 0.0159200 secs] [Times: user=0.12 sys=0.00, real=0.02 secs] 
2019-03-21T11:19:47.085+0800: 1086351.452: [Rescan (parallel) , 0.0106023 secs]2019-03-21T11:19:47.096+0800: 1086351.462: [weak refs processing, 0.0000353 secs]2019-03-21T11:19:47.096+0800: 1086351.462: [class unloading, 0.0421021 secs]2019-03-21T11:19:47.138+0800: 1086351.505: [scrub symbol table, 0.0157111 secs]2019-03-21T11:19:47.153+0800: 1086351.520: [scrub string table, 0.0014866 secs][1 CMS-remark: 2203030K(3145728K)] 2226423K(4089472K), 0.0887818 secs] [Times: user=0.26 sys=0.01, real=0.09 secs] 
2019-03-21T11:19:47.158+0800: 1086351.525: [CMS-concurrent-sweep-start]
2019-03-21T11:19:47.350+0800: 1086351.717: [CMS-concurrent-sweep: 0.192/0.192 secs] [Times: user=0.31 sys=0.00, real=0.20 secs] 
2019-03-21T11:19:47.351+0800: 1086351.717: [CMS-concurrent-reset-start]
2019-03-21T11:19:47.356+0800: 1086351.723: [CMS-concurrent-reset: 0.005/0.005 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

ParNew GC

1
2019-03-21T11:19:41.609+0800: 1086345.976: [GC (Allocation Failure) 2019-03-21T11:19:41.609+0800: 1086345.976: [ParNew: 873168K->36622K(943744K), 0.0312849 secs] 3074543K->2238776K(4089472K), 0.0316707 secs] [Times: user=0.14 sys=0.00, real=0.04 secs]
  1. GC：区别MinorGC和FullGC的标识，这里代表的是MinorGC;
  2. Allocation Failure：MinorGC的原因，在这里由于年轻代不满足申请的空间，因此触发了MinorGC(年轻代GC);
  3. ParNew：收集器的类型，它预示了年轻代使用一个并行的mark-copy垃圾收集器；
  4. 873168K->36622K：收集前后年轻代的使用情况；
  5. 943744K： 整个年轻代的容量；
  6. 3074543K->2238776K：收集前后整个堆的使用情况；
  7. 4089472K：整个堆的容量；
  8. 0.0316707 secs：ParNew收集器标记和复制年轻代活着的对象所花费的时间（包括和老年代通信的开销、对象晋升到老年代时间、垃圾收集周期结束最后的清理对象等的花销）；
  9. [Times: user=0.14 sys=0.00, real=0.04 secs]：GC事件在不同维度的耗时:
    • user：GC线程在垃圾收集期间所使用的CPU总时间；
    • sys：系统调用或者等待系统事件花费的时间；
    • real：应用被暂停的时钟时间，由于GC线程是多线程的，导致了real小于user+real，如果是GC线程是单线程的话，real是接近于user+real时间。

CMS GC

CMS GC是基于标记-清除算法实现的，整个过程分几步：

  1. 初始标记(initial-mark)：从GC Root开始，仅扫描与根节点直接关联的对象并标记，这个过程需要STW，但是GC Root数量有限，因此时间较短
  2. 并发标记(concurrent-marking)：这个阶段在初始标记的基础上继续向下进行遍历标记。这个阶段与用户线程并发执行，因此不停顿
  3. 并发预清理(concurrent-precleaning)：该阶段并发执行，应用不停顿；在并发标记阶段执行期间，会出现一些刚刚晋升老年代的对象或新分配的对象，该阶段通过重新扫描减少下一阶段的工作；precleaning是为了减少下一阶段“重新标记”的工作量，因为remark阶段会STW
  4. 可终止的预清理(Concurrent Abortable Preclean)：可中止预清理阶段，运行在并发预清理和重新标记之间，直到获得所期望的eden空间占用率。不会暂停应用，继续预清理，直到eden区占用量达到CMSScheduleRemarkEdenPenetration(默认50%)或达到5秒钟
  5. 重新标记(remark)：修正并发标记期间因用户程序继续运作而导致标记产生变动的那一部分对象的标记记录，以保证执行清理之前对象引用关系是正确的。这一阶段需要STW，时间也比较短暂
  6. 并发清理(concurrent-sweeping)：清理垃圾对象，这个过程与用户线程并发执行，不停顿
  7. 并发重置(reset)：重置CMS收集器的数据结构，做好下一次执行GC任务的准备工作

整个过程中需要STW的阶段仅有初始标记和重新标记阶段，所以可以说它的停顿时间比较短

参考

https://plumbr.io/handbook/garbage-collection-algorithms-implementations/concurrent-mark-and-sweep

(推荐)GC之详解CMS收集过程和日志分析

CMS: abort preclean due to time

Java CMS GC 361s引发的血案

热评文章