记一次 SIT 环境由 MyBatis 拦截器引发的 Full GC 排查

背景

最近在 SIT 环境进行全链路拉通测试时，监控系统发出了告警。在测试同学执行大批量数据处理（18:00 ~ 21:18）期间，某核心服务频繁触发 Full GC，平均频率达到每分钟 40 次，导致服务几乎处于不可用状态。

应用启动参数配置了较大的堆内存（10GB）：

-Xms10240m -Xmx10240m -XX:MetaspaceSize=200M ...

按理说，10GB 的堆内存在非生产环境应付常规测试绰绰有余，如此高频的 Full GC 显然不正常。

排查过程

1. 监控分析

查看 GC 日志和应用监控，发现以下特征：

• 内存详情：Old Gen（老年代）被迅速填满，GC 回收效果极差。
• CPU 飙升：伴随着 GC，CPU 使用率居高不下。
• 线程异常：监控显示 ForkJoinPool.commonPool-worker-* 系列线程占用了大量的 CPU 时间和内存（统计显示该池累计关联内存高达 100GB+，意味着大量对象在线程中流转）。

2. 线程堆栈定位

抓取当时的 Thread Dump，发现大量 ForkJoinPool 的 Worker 线程处于 RUNNABLE 状态，且堆栈惊人的一致，全部卡在正则表达式的匹配上：

"ForkJoinPool.commonPool-worker-3" Id=31233 RUNNABLE
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3811)
    at java.util.regex.Matcher.search(Matcher.java:1248)
    at java.util.regex.Matcher.find(Matcher.java:637)
    ...

顺着堆栈向下追溯，定位到了我们项目中的一个 MyBatis 拦截器 LastQueryHandler。该拦截器的初衷是记录用户的最后一次查询 SQL 以便排查问题。

3. 代码分析

经过脱敏后的核心代码逻辑如下：

// 拦截器逻辑
@Override
public void beforeQuery(..., Object parameter, BoundSql boundSql) {
    // 异步执行日志记录
    CompletableFuture.runAsync(() -> {
        try {
            // 拼接完整 SQL (将 ? 替换为实际参数)
            String sql = showSql(configuration, boundSql);
            // 去除换行符等
            String formattedSql = sql.replaceAll("\\s+", " ").trim();
            // 存入 Redis
            saveToRedis(formattedSql);
        } catch (Exception e) { ... }
    });
}

// 拼接 SQL 的工具方法
public static String showSql(Configuration configuration, BoundSql boundSql) {
    String sql = boundSql.getSql();
    // ... 获取参数映射 ...
    for (ParameterMapping mapping : parameterMappings) {
        // 问题点：在循环中频繁使用正则替换
        sql = sql.replaceFirst("\\?", Matcher.quoteReplacement(getParameterValue(obj)));
    }
    return sql;
}

根因分析

结合代码和堆栈，我们还原了导致内存溢出的完整链路。这是一个典型的“生产-消费模型失衡”与“低效算法”共同作用的结果。

1. 隐形的线程池陷阱

代码中使用 CompletableFuture.runAsync(...) 且未指定 Executor，默认使用的是 JVM 全局共享的 ForkJoinPool.commonPool()。

• 该线程池的并发度默认为 CPU核心数 - 1（在测试服务器上仅为 15 个线程）。
• 这是一个无界队列。

2. 消费端阻塞：低效的正则

showSql 方法在循环中对 SQL 字符串执行 replaceFirst。

• CPU 杀手：对于包含大量参数的 Batch Insert 语句（例如一次插入 500 条数据，每条 10 个字段，就是 5000 个参数），循环执行 5000 次正则匹配。
• 内存杀手：Java 中 String 是不可变的。每次 replaceFirst 都会生成一个新的 String 对象。

这导致 ForkJoinPool 的 15 个线程被死死卡住，处理一条 SQL 日志可能需要数百毫秒。

3. 生产端倾泻：单线程的假象

这里有一个极具迷惑性的点：我们的 RocketMQ 消费者配置为单线程：

@RocketMQMessageListener(..., consumeThreadNumber = 1)

误区：我们以为限制了消费线程数为 1，系统压力就不会大。
真相：
RocketMQ 消费线程（生产者）处理业务极快，它只负责调用 CompletableFuture.runAsync 提交任务，然后立刻去拉取下一条消息。

• 生产者速度：100 QPS（假设）。
• 消费者速度：因为正则卡顿，ForkJoinPool 每秒只能处理 5 个任务。

结果：
任务以每秒 95 个的速度在内存中积压。每个任务都持有一个 Lambda 闭包，闭包中强引用了巨大的 parameter 对象（业务数据）。这些对象排队等待执行，无法被 GC 回收，迅速填满了 10GB 的老年代。

解决方案

找到病灶后，优化方案就呼之欲出了。我们进行了三步改造：

Step 1: 线程隔离与背压控制（必须）

绝对不能使用公共线程池处理非核心业务。我们引入了一个有界队列的线程池，并配置了丢弃策略。

private final ExecutorService logExecutor = new ThreadPoolExecutor(
    2, 4, 60L, TimeUnit.SECONDS,
    new LinkedBlockingQueue<>(100), // 队列限制 100
    new ThreadFactoryBuilder().setNameFormat("sql-log-%d").build(),
    new ThreadPoolExecutor.DiscardPolicy() // 满载直接丢弃，保护主程序
);

Step 2: 移除低效正则

生产环境的日志应当尽量轻量。我们去掉了 showSql 中复杂的参数拼接逻辑，仅记录 SQL 模板和关键信息。如果确实需要拼接，必须限制 SQL 长度和参数数量，避免处理批量操作的大 SQL。

// 优化后：仅做简单格式化，不做参数深层拼接
String finalSql = boundSql.getSql().replaceAll("\\s+", " ").trim();
if (finalSql.length() > 5000) {
    finalSql = finalSql.substring(0, 5000) + "...(truncated)";
}

Step 3: 数据解耦

在提交异步任务前，提取出必要的字符串信息（String），而不是把整个业务对象（Object parameter）传给异步线程。这样即使任务排队，占用的内存也仅仅是几个字符串，而不是庞大的业务数据。

总结

这次 SIT 环境的 Full GC 事故提醒我们：

1. 慎用默认线程池：CompletableFuture 的默认线程池在生产场景下极易成为隐患。
2. 警惕异步闭包：异步任务中引用的对象在任务执行完之前是不会被释放的，高并发下容易引发 OOM。
3. 正则操作要克制：在循环中处理大字符串的正则替换是性能的大忌。

通过优化，应用在后续的压测中表现平稳，内存和 CPU 曲线恢复正常。