GC: CMS垃圾回收器三（实践）

jstat -gc -t [pid] 1000 监控日志... ，抽取其中关键记录不一定连续

应用启动时间 2015-06-23 10:22:27 ，换算后，第二条记录时间是2015-06-24 22:35:16 ，转换过程中有毫秒级的误差，与GC日志一致。

Timestamp	S0C	S1C	S0U	S1U	EC	EU	OC	OU	PC	PU	YGC	YGCT	FGC	FGCT	GCT
130368.2	209664.0	209664.0	142366.4	0.0	1677824.0	1677824.0	2097152.0	1043374.3	131072.0	15537.9	80	18.274	0	0.000	18.274
130369.2	209664.0	209664.0	0.0	137896.2	1677824.0	19949.5	2097152.0	1054947.1	131072.0	15537.9	81	18.532	1	0.039	18.571
130374.3	209664.0	209664.0	0.0	137896.2	1677824.0	33201.4	2097152.0	1054837.5	131072.0	15537.9	81	18.532	2	0.076	18.608

以下是开启-XX:+PrintGCDetails -XX:+PrintGCDateStamps 后的部分日志：

第一步：CMS-initial-mark

2015-06-24T22:35:17.084+0800: 130368.643: [GC [1 CMS-initial-mark: 1054947K(2097152K)] 1193557K(3984640K), 0.0386010 secs] [Times: user=0.03 sys=0.00, real=0.04 secs]

本例中启动参数未设置-XX:+UseCMSInitiatingOccupancyOnly ，只设置了-XX:CMSInitiatingOccupancyFraction=70 ，系统根据统计数据自行决定50%触发cms gc ，而不是在70%时候。

格式： PrintGCDateStamps部分 [GC [1 CMS-initial-mark: OU(OC)] SU+EU+OU(-Xmx), 耗时] []

第二步：CMS-concurrent-mark

2015-06-24T22:35:17.125+0800: 130368.684: [CMS-concurrent-mark-start]

2015-06-24T22:35:17.152+0800: 130368.711: [CMS-concurrent-mark: 0.027/0.027 secs] [Times: user=0.16 sys=0.00, real=0.03 secs]

第三步：CMS-concurrent-preclean

2015-06-24T22:35:17.153+0800: 130368.712: [CMS-concurrent-preclean-start]

2015-06-24T22:35:17.164+0800: 130368.723: [CMS-concurrent-preclean: 0.011/0.011 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]

第四步：CMS-concurrent-abortable-preclean

2015-06-24T22:35:17.164+0800: 130368.723: [CMS-concurrent-abortable-preclean-start]

CMS: abort preclean due to time 2015-06-24T22:35:22.481+0800: 130374.041: [CMS-concurrent-abortable-preclean: 5.216/5.317 secs] [Times: user=6.14 sys=0.11, real=5.32 secs]

第五步：CMS-remark

2015-06-24T22:35:22.486+0800: 130374.045: [GC[YG occupancy: 171097 K (1887488 K)]2015-06-24T22:35:22.486+0800: 130374.045: [Rescan (parallel) , 0.0175320 secs]2015-06-24T22:35:22.504+0800: 130374.063: [weak refs processing, 0.0005460 secs]2015-06-24T22:35:22.505+0800: 130374.064: [class unloading, 0.0074730 secs]2015-06-24T22:35:22.512+0800: 130374.071: [scrub symbol table, 0.0054870 secs]2015-06-24T22:35:22.518+0800: 130374.077: [scrub string table, 0.0013050 secs] [1 CMS-remark: 1054947K(2097152K)] 1226044K(3984640K), 0.0372980 secs] [Times: user=0.25 sys=0.00, real=0.04 secs]

第六步：CMS-concurrent-sweep-start

2015-06-24T22:35:22.525+0800: 130374.084: [CMS-concurrent-sweep-start]

2015-06-24T22:35:22.546+0800: 130374.105: [CMS-concurrent-sweep: 0.021/0.021 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]

第七步：CMS-concurrent-reset

2015-06-24T22:35:22.547+0800: 130374.106: [CMS-concurrent-reset-start]

2015-06-24T22:35:22.564+0800: 130374.123: [CMS-concurrent-reset: 0.017/0.017 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]