问题
在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 秒内完成。
