CMS GC日志分析

Young GC：

GC (Allocation Failure) [ParNew...]

2020-03-20T15:59:50.339+0800: 261.249: [GC (Allocation Failure) 2020-03-20T15:59:50.339+0800: 261.249: [ParNew: 674570K->11905K(707840K), 0.0206578 secs] 1231009K->568345K(2018560K), 0.0208913 secs] [Times: user=0.37 sys=0.05, real=0.02 secs]
2020-03-20T16:00:03.181+0800: 274.091: [GC (Allocation Failure) 2020-03-20T16:00:03.181+0800: 274.091: [ParNew: 641153K->78592K(707840K), 0.0569508 secs] 1197593K->656714K(2018560K), 0.0571824 secs] [Times: user=0.97 sys=0.15, real=0.05 secs]
2020-03-20T16:00:22.115+0800: 293.025: [GC (Allocation Failure) 2020-03-20T16:00:22.115+0800: 293.025: [ParNew: 707840K->59717K(707840K), 0.0736715 secs] 1285962K->716358K(2018560K), 0.0739082 secs] [Times: user=0.53 sys=0.16, real=0.08 secs]

Full GC

1、初始化标记阶段：stop the world

这个是 CMS 两次 stop-the-wolrd 事件的其中一次，这个阶段的目标是：标记那些直接被 GC root 引用或者被年轻代存活对象所引用的所有对象
2020-03-20T16:00:22.190+0800: 293.100: [GC (CMS Initial Mark) [1 CMS-initial-mark: 656640K(1310720K)] 716434K(2018560K), 0.0053335 secs] [Times: user=0.01 sys=0.05, real=0.00 secs]

2、
2020-03-20T16:00:22.195+0800: 293.105: [CMS-concurrent-mark-start]
2020-03-20T16:00:22.253+0800: 293.163: [CMS-concurrent-mark: 0.058/0.058 secs] [Times: user=0.36 sys=0.03, real=0.06 secs]

3、
2020-03-20T16:00:22.253+0800: 293.163: [CMS-concurrent-preclean-start]
2020-03-20T16:00:22.259+0800: 293.169: [CMS-concurrent-preclean: 0.005/0.006 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

4、
2020-03-20T16:00:22.259+0800: 293.169: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2020-03-20T16:00:27.261+0800: 298.171: [CMS-concurrent-abortable-preclean: 0.694/5.003 secs] [Times: user=1.92 sys=0.58, real=5.00 secs]

5、Final Remark：stop the world

这是第二个 STW 阶段，也是 CMS 中的最后一个，这个阶段的目标是标记所有老年代所有的存活对象，由于之前的阶段是并发执行的，gc 线程可能跟不上应用程序的变化，为了完成标记老年代所有存活对象的目标，STW 就非常有必要了

2020-03-20T16:00:27.263+0800: 298.173: [GC (CMS Final Remark) [YG occupancy: 238519 K (707840 K)]2020-03-20T16:00:27.263+0800: 298.173: [GC (CMS Final Remark) 2020-03-20T16:00:27.263+0800: 298.173: [ParNew: 238519K->14964K(707840K), 0.0190550 secs] 895160K->671605K(2018560K), 0.0191841 secs] [Times: user=0.37 sys=0.04, real=0.02 secs]

6、Rescan (parallel)：Rescan阶段(remark阶段的一个子阶段)会扫描新生代和老年代中的对象，并行的，不会stw
2020-03-20T16:00:27.282+0800: 298.192: [Rescan (parallel) , 0.0029723 secs]2020-03-20T16:00:27.285+0800: 298.195: [weak refs processing, 0.0001010 secs]2020-03-20T16:00:27.285+0800: 298.195: [class unloading, 0.0691184 secs]2020-03-20T16:00:27.354+0800: 298.264: [scrub symbol table, 0.0180493 secs]2020-03-20T16:00:27.372+0800: 298.282: [scrub string table, 0.0016066 secs][1 CMS-remark: 656640K(1310720K)] 671605K(2018560K), 0.1164599 secs] [Times: user=0.48 sys=0.07, real=0.12 secs]

7、
2020-03-20T16:00:27.379+0800: 298.289: [CMS-concurrent-sweep-start]
2020-03-20T16:00:27.955+0800: 298.865: [CMS-concurrent-sweep: 0.576/0.576 secs] [Times: user=0.67 sys=0.10, real=0.57 secs]

8、
2020-03-20T16:00:27.955+0800: 298.865: [CMS-concurrent-reset-start]
2020-03-20T16:00:27.967+0800: 298.877: [CMS-concurrent-reset: 0.012/0.012 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]
2020-03-20T16:00:45.398+0800: 316.308: [GC (Allocation Failure) 2020-03-20T16:00:45.398+0800: 316.308: [ParNew: 644145K->4056K(707840K), 0.0079048 secs] 830243K->190154K(2018560K), 0.0080658 secs] [Times: user=0.10 sys=0.05, real=0.01 secs]
2020-03-20T16:01:00.124+0800: 331.034: [GC (Allocation Failure) 2020-03-20T16:01:00.124+0800: 331.034: [ParNew: 633304K->52986K(707840K), 0.0199449 secs] 819402K->239085K(2018560K), 0.0201486 secs] [Times: user=0.24 sys=0.18, real=0.02 secs]
2020-03-20T16:01:15.544+0800: 346.454: [GC (Allocation Failure) 2020-03-20T16:01:15.544+0800: 346.454: [ParNew: 682234K->72237K(707840K), 0.0530787 secs] 868333K->308908K(2018560K), 0.0533124 secs] [Times: user=0.57 sys=0.15, real=0.05 secs]
2020-03-20T16:01:33.093+0800: 364.003: [GC (Allocation Failure) 2020-03-20T16:01:33.093+0800: 364.003: [ParNew: 701485K->47316K(707840K), 0.0391919 secs] 938156K->333576K(2018560K), 0.0393911 secs] [Times: user=0.32 sys=0.09, real=0.04 secs]
2020-03-20T16:01:50.444+0800: 381.354: [GC (Allocation Failure) 2020-03-20T16:01:50.444+0800: 381.354: [ParNew: 676562K->10836K(707840K), 0.0088645 secs] 962822K->297096K(2018560K), 0.0090511 secs] [Times: user=0.08 sys=0.08, real=0.01 secs]
2020-03-20T16:02:02.727+0800: 393.637: [GC (Allocation Failure) 2020-03-20T16:02:02.727+0800: 393.637: [ParNew: 640084K->78592K(707840K), 0.0559518 secs] 926344K->389351K(2018560K), 0.0561502 secs] [Times: user=0.99 sys=0.11, real=0.06 secs]

 

参考：https://www.jianshu.com/p/cd591e2f7946