gc.log中 CMS-concurrent-abortable-preclean

问题

在gc日志中看到

2024-06-26T16:16:07.504+0800: 64690272.666: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2024-06-26T16:16:12.553+0800: 64690277.716: [CMS-concurrent-abortable-preclean: 1.052/5.049 secs] [Times: user=1.33 sys=0.00, real=5.04 secs]

是什么原因呢，是否需要关注呢

gc日志

2024-06-26T16:16:06.892+0800: 64690272.055: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2856872K(3276800K)] 3544903K(5046272K), 0.1588617 secs] [Times: user=0.31 sys=0.00, real=0.16 secs]
2024-06-26T16:16:07.051+0800: 64690272.214: [CMS-concurrent-mark-start]
2024-06-26T16:16:07.495+0800: 64690272.658: [CMS-concurrent-mark: 0.444/0.444 secs] [Times: user=0.44 sys=0.00, real=0.45 secs]
2024-06-26T16:16:07.495+0800: 64690272.658: [CMS-concurrent-preclean-start]
2024-06-26T16:16:07.504+0800: 64690272.666: [CMS-concurrent-preclean: 0.008/0.009 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2024-06-26T16:16:07.504+0800: 64690272.666: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2024-06-26T16:16:12.553+0800: 64690277.716: [CMS-concurrent-abortable-preclean: 1.052/5.049 secs] [Times: user=1.33 sys=0.00, real=5.04 secs]
2024-06-26T16:16:12.555+0800: 64690277.717: [GC (CMS Final Remark) [YG occupancy: 780007 K (1769472 K)]2024-06-26T16:16:12.555+0800: 64690277.717: [Rescan (parallel) , 0.2045689 secs]2024-06-26T16:16:12.760+0800: 64690277.922: [weak refs processing, 0.0001818 secs]
2024-06-26T16:16:12.760+0800: 64690277.922: [class unloading, 0.0423633 secs]
2024-06-26T16:16:12.802+0800: 64690277.965: [scrub symbol table, 0.0224709 secs]
2024-06-26T16:16:12.825+0800: 64690277.987: [scrub string table, 0.0025649 secs][1 CMS-remark: 2856872K(3276800K)] 3636880K(5046272K), 0.2724005 secs] [Times: user=0.47 sys=0.00, real=0.27 secs]
2024-06-26T16:16:12.828+0800: 64690277.990: [CMS-concurrent-sweep-start]
2024-06-26T16:16:12.975+0800: 64690278.138: [CMS-concurrent-sweep: 0.148/0.148 secs] [Times: user=0.15 sys=0.00, real=0.15 secs]
2024-06-26T16:16:12.975+0800: 64690278.138: [CMS-concurrent-reset-start]
2024-06-26T16:16:12.986+0800: 64690278.149: [CMS-concurrent-reset: 0.011/0.011 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

分析原因

从日志可以看到 CMS 收集器经历了以下阶段，其中只有两个阶段是STW:

阶段	类型	原因
CMS Initial Mark	stop-the-world	标记对象
CMS-concurrent-mark	concurrent	并发标记
CMS-concurrent-preclean	concurrent	并发预清理
CMS-concurrent-abortable-preclean	concurrent	可中止预清理
CMS Final Remark	stop-the-world	最终标记
CMS-concurrent-sweep	concurrent	并发扫描
CMS-concurrent-reset	concurrent	并发复位

如果可中止的预清理阶段CMS-concurrent-abortable-preclean超过了CMSMaxAbortablePrecleanTime的值，就会打印上述日志，默认为 5 秒。如果超过这个阶段，它就会中止这个阶段并继续进入下一个阶段。

如果重复打印此消息，则表示它无法在 5 秒内完成预清理阶段。要么需要增加时间以允许更长的预清理阶段，要么需要检查操作系统或堆以确定为什么没有在分配的 5 秒内完成。

查看当前的CMSMaxAbortablePrecleanTime配置

根因

预清理阶段有助于减少下一个“最终标记”阶段的工作。中止第二个预清理阶段是预期行为。它被中止并不表示有错误。如果重复打印此消息，则表示它无法在 5 秒内完成预清理阶段。要么需要增加时间以允许更长的预清理阶段，要么需要检查操作系统或堆以确定为什么没有在分配的 5 秒内完成。