那天下午运维突然在群里@我，说线上有个服务内存快撑爆了，GC 日志刷得跟心电图似的，几乎每十几秒就一次 Full GC。我第一反应是“不至于吧，这服务半个月前刚优化过 JVM 参数”，登上监控一看，老年代使用率在 80% 到 99% 之间疯狂抖动，应用吞吐量直接腰斩。
我翻出 GC 日志，好家伙，十几兆的日志文件里密密麻麻全是 [Full GC (Allocation Failure) 和 [CMS-concurrent-mark: ...]。按经验，这种高频 Full GC 要么是内存泄漏，要么是晋升过快。我先用 jmap 抓了个堆 dump，用 MAT 分析了半天，发现对象都很正常，生命周期符合预期，没有任何一个类占用异常。这就奇怪了，既然没有泄漏，为什么老年代会这么快被打满？
折腾到傍晚，我决定甩开 IDE，自己写个小脚本把 GC 日志里的关键数据捞出来看看。既然人工翻日志像大海捞针，那就让代码替我干活。需求很明确：从 CMS GC 日志里提取出每次 Young GC 的暂停时间、晋升大小，以及每次 Full GC 前后的老年代使用量，按时间线排列，然后统计出什么情况下最容易触发 Full GC。
核心解析逻辑大概是这样的，先定义几个正则把 CMS 日志里的数字抓出来：
# 匹配 Young GC 行，CMS 日志类似：
# 2023-07-21T14:23:04.218+0800: 130082.456: [GC (Allocation Failure) ...
# ... 64672K->7762K(251392K), 0.0723169 secs]
YOUNG_GC_PATTERN = re.compile(r'(\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.\d{3}[+-]\d{4}):\s+'r'(\d+\.\d+):\s+\[GC \(Allocation Failure\).*?'r'(\d+)K->(\d+)K\((\d+)K\),\s+([\d.]+)\s+secs\]'
)# 匹配 CMS 初始标记和最终标记，用来捕获老年代变化
CMS_INITIAL_MARK = re.compile(r'(\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.\d{3}[+-]\d{4}):\s+'r'(\d+\.\d+):\s+\[GC \(CMS Initial Mark\).*?'r'(\d+)K\((\d+)K\).*?'
)
CMS_REMARK = re.compile(r'(\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.\d{3}[+-]\d{4}):\s+'r'(\d+\.\d+):\s+\[GC \(CMS Final Remark\).*?'r'(\d+)K->(\d+)K\((\d+)K\).*?'
)# Full GC 模式，包括 Allocation Failure 和 concurrent mode failure
FULL_GC_PATTERN = re.compile(r'(\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.\d{3}[+-]\d{4}):\s+'r'(\d+\.\d+):\s+\[Full GC.*?'r'(\d+)K->(\d+)K\((\d+)K\),\s+([\d.]+)\s+secs\]'
)
把文件一行行喂进去，解析成结构化数据，然后我想看的其实是“每次 Young GC 到底往老年代扔了多少数据”。CMS 日志里虽然不直接写晋升量，但可以通过两次 GC 之间老年代已用空间的变化来推算——毕竟 Full GC 之前的 Young GC 往往伴随着大量对象熬过了一定年龄被挪到老年代。于是脚本里加了一个简单的状态追踪：记录上一次 Young GC 结束后老年代可用空间，再对比下一次 Young GC 之前的老年代占用量，差值基本就是这中间晋升过去的大小。
后来我又补了一段聚合统计的代码，把时间窗口里的晋升速率算出来：
promotion_records = []
prev_old_used = initial_old_used # 从日志开头解析到的初始值for event in gc_events:if event['type'] == 'young_gc':# 这次 Young GC 结束后，老年代还剩下多少可用空间？# 日志里 young_gc 行本身不直接给老年代数据，但可以通过最近的 full_gc 或初始标记算出来# 这里简化处理，假设我们维护着一个 current_old_usagepromotion = max(0, current_old_usage - prev_old_used)promotion_records.append({'timestamp': event['timestamp'],'promotion_kb': promotion,'young_gc_time': event['duration']})prev_old_used = current_old_usage
等到统计结果出来，我一眼就发现了问题：每次 Young GC 后，几乎都有 400MB 左右的对象被直接搬到老年代，而这个服务新生代总共才配了 256MB。这意味着大量对象熬过了太多次 Minor GC，甚至都没在 Survivor 区待够就冲进了老年代。顺着这个思路我去看 JVM 启动参数，果然发现了一个隐蔽的配置：-XX:MaxTenuringThreshold=15。
这参数本身没问题，但它配合了另一个不易察觉的默认值——CMS 下 UseAdaptiveSizePolicy 在某些 JDK 版本里默认是开启的，它会动态调整 Survivor 区大小和晋升阈值。我线上环境跑的正是那个踩坑的版本，动态调整策略会把 Survivor 区压到极小，导致绝大多数对象活不过一次 Minor GC 就被迫晋升。更要命的是，MaxTenuringThreshold 设置为 15，实际上自适应策略内部可能早就把它调成了 1，但日志里不会显式告诉你。我当时注入的参数优先级又没显式关闭自适应，等于白设。
把 -XX:-UseAdaptiveSizePolicy 加上，同时显式指定 -XX:SurvivorRatio=8，重启后效果立竿见影：Young GC 晋升量从 400MB 骤降到几十 MB，老年代使用率平稳在 30% 左右，Full GC 基本消失，CPU 负载也降了下来。
回头想想，这一整天就耗在了一个自适应策略的暗坑上。但话说回来，要不是自己随手撸了个日志分析的脚本，单靠肉眼扫几十兆日志根本不可能把晋升规律揪出来。这个小工具后来我改良了一下，支持分析 G1 和 ZGC 的日志，挂上定时任务用来做离线预警，比干盯着监控曲线有用多了。脚本的核心价值也就是这一点：把隐晦的运行时行为，翻译成能比较的数字，那些看似诡异的线上问题，往往就这么被一组统计值给暴露了。