[Java] 基于MyBatis拦截器优化SQL日志格式，有效降低30%存储成本

背景

在使用MyBatis Plus时，我们通常通过配置文件设置 log-impl 属性来指定日志实现，从而在控制台打印执行的SQL语句。

mybatis-plus:
  configuration:
    log-impl: org.apache.ibatis.logging.stdout.StdOutImpl

logging:
  level:
    org.ylzl.eden.demo.mapper: DEBUG

配置后，打印出来的SQL内容格式如下：

==>  Preparing: SELECT id,login,email,activated,locked,lang_key,activation_key,reset_key,reset_date,created_by,created_date,last_modified_by,last_modified_date FROM demo_user WHERE id=?
==> Parameters: 1(Long)
<==  Columns: ID, LOGIN, EMAIL, ACTIVATED, LOCKED, LANG_KEY, ACTIVATION_KEY, RESET_KEY, RESET_DATE, CREATED_BY, CREATED_DATE, LAST_MODIFIED_BY, LAST_MODIFIED_DATE
<==  Row: 1, admin, 1813986321@qq.com, TRUE, FALSE, zh-cn, null, null, null, system, 2025-02-10 22:31:03.818, system, null
<==  Total: 1

然而，这种默认的日志输出格式在实际生产环境中存在几个明显的不足：

• 缺少执行时间戳：无法快速定位SQL的具体执行时间，不利于问题排查与性能分析。
• 可读性较差：SQL语句与参数分离，对于复杂的多条件查询，需要手动拼接才能理解完整的语义，阅读成本高。
• 存储成本高昂：日志中包含了大量固定的模板字符（如 ==> Preparing:、==> Parameters:），这些重复内容显著增加了日志文件的体积，从而推高了存储成本。

目标

为了解决上述问题，我们的目标是绕过MyBatis默认的日志机制，通过自定义 MyBatis拦截器 来直接捕获并格式化SQL信息，输出更简洁、信息更完整的日志。

实现

1. 自定义MyBatis拦截器

首先，我们需要创建一个自定义拦截器，实现 org.apache.ibatis.plugin.Interceptor 接口。这个拦截器的核心作用是拦截Executor的query和update方法，在执行前后记录时间，并获取最终要执行的SQL语句。

@Intercepts({
        @Signature(method = "query", type = Executor.class, args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}),
        @Signature(method = "query", type = Executor.class, args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class, CacheKey.class, BoundSql.class}),
        @Signature(method = "update", type = Executor.class, args = {MappedStatement.class, Object.class})
})
public class MybatisSqlLogInterceptor implements Interceptor {

    private static final Logger log = LoggerFactory.getLogger("MybatisSqlLog");

    private Duration slownessThreshold = Duration.ofMillis(1000);

    @Override
    public Object intercept(Invocation invocation) throws Throwable {
        MappedStatement mappedStatement = (MappedStatement) invocation.getArgs()[0];
        String mapperId = mappedStatement.getId();

        // 获取可执行的完整SQL
        String originalSql = MybatisUtils.getSql(mappedStatement, invocation);

        long start = SystemClock.now();
        Object result = invocation.proceed();
        long duration = SystemClock.now() - start;

        // 当 SQL 执行超过我们设置的阈值，转为 WARN 级别
        if (Duration.ofMillis(duration).compareTo(slownessThreshold) < 0) {
            log.info("{} execute sql: {} ({} ms)", mapperId, originalSql, duration);
        } else {
            log.warn("{} execute sql took more than {} ms: {} ({} ms)", mapperId, slownessThreshold.toMillis(), originalSql, duration);
        }
        return result;
    }

    @Override
    public Object plugin(Object target) {
        if (target instanceof Executor) {
            return Plugin.wrap(target, this);
        }
        return target;
    }

    // 设置慢 SQL 阈值，单位为秒
    public void setSlownessThreshold(Duration slownessThreshold) {
        this.slownessThreshold = slownessThreshold;
    }
}

2. SQL解析工具类

上面的拦截器依赖一个工具类 MybatisUtils 来解析 MappedStatement 和参数，将带有占位符?的SQL模板还原为参数已填充的、可直接执行的完整SQL字符串。这是实现后端架构中日志优化的关键一步。

@UtilityClass
public class MybatisUtils {

    private static final Pattern PARAMETER_PATTERN = Pattern.compile("\\?");

    public String getSql(MappedStatement mappedStatement, Invocation invocation) {
        Object parameter = null;
        if (invocation.getArgs().length > 1) {
            parameter = invocation.getArgs()[1];
        }
        BoundSql boundSql = mappedStatement.getBoundSql(parameter);
        Configuration configuration = mappedStatement.getConfiguration();
        return resolveSql(configuration, boundSql);
    }

    private static String resolveSql(Configuration configuration, BoundSql boundSql) {
        Object parameterObject = boundSql.getParameterObject();
        List<ParameterMapping> parameterMappings = boundSql.getParameterMappings();
        String sql = boundSql.getSql().replaceAll("[\\s]+", " ");
        if (!parameterMappings.isEmpty() && parameterObject != null) {
            TypeHandlerRegistry typeHandlerRegistry = configuration.getTypeHandlerRegistry();
            if (typeHandlerRegistry.hasTypeHandler(parameterObject.getClass())) {
                sql = sql.replaceFirst("\\?", Matcher.quoteReplacement(resolveParameterValue(parameterObject)));

            } else {
                MetaObject metaObject = configuration.newMetaObject(parameterObject);
                Matcher matcher = PARAMETER_PATTERN.matcher(sql);
                StringBuffer sqlBuffer = new StringBuffer();
                for (ParameterMapping parameterMapping : parameterMappings) {
                    String propertyName = parameterMapping.getProperty();
                    Object obj = null;
                    if (metaObject.hasGetter(propertyName)) {
                        obj = metaObject.getValue(propertyName);
                    } else if (boundSql.hasAdditionalParameter(propertyName)) {
                        obj = boundSql.getAdditionalParameter(propertyName);
                    }
                    if (matcher.find()) {
                        matcher.appendReplacement(sqlBuffer, Matcher.quoteReplacement(resolveParameterValue(obj)));
                    }
                }
                matcher.appendTail(sqlBuffer);
                sql = sqlBuffer.toString();
            }
        }
        return sql;
    }

    private static String resolveParameterValue(Object obj) {
        if (obj instanceof CharSequence) {
            return "'" + obj + "'";
        }
        if (obj instanceof Date) {
            DateFormat formatter = DateFormat.getDateTimeInstance(DateFormat.DEFAULT, DateFormat.DEFAULT, Locale.CHINA);
            return "'" + formatter.format(obj) + "'";
        }
        return obj == null ? "" : String.valueOf(obj);
    }
}

3. Spring Boot自动配置

为了使拦截器便于管理和配置，我们将其包装为一个Spring Boot Starter的自动配置类，通过配置文件属性来控制其启用和慢SQL阈值。

@AutoConfigureAfter(DataSourceAutoConfiguration.class)
@ConditionalOnBean(SqlSessionFactory.class)
@ConditionalOnProperty(name = "mybatis.plugin.sql-log.enabled")
@EnableConfigurationProperties({MybatisPluginProperties.class})
@RequiredArgsConstructor
@Slf4j
@Role(BeanDefinition.ROLE_INFRASTRUCTURE)
@Configuration(proxyBeanMethods = false)
public class MybatisPluginAutoConfiguration {

    private final MybatisPluginProperties mybatisPluginProperties;

    @Bean
    public MybatisSqlLogInterceptor mybatisSqlLogInterceptor() {
        MybatisSqlLogInterceptor interceptor = new MybatisSqlLogInterceptor();
        interceptor.setSlownessThreshold(mybatisPluginProperties.getSqlLog().getSlownessThreshold());
        return interceptor;
    }
}

对应的配置属性类：

@Data
@ConfigurationProperties(prefix = "mybatis.plugin")
public class MybatisPluginProperties {

    private final SqlLog sqlLog = new SqlLog();

    @Data
    public static class SqlLog {

        private boolean enabled = true;

        private Duration slownessThreshold = Duration.ofMillis(1000);
    }
}

效果

当在项目的 application.yml 中配置 mybatis.plugin.sql-log.enabled=true 后，SQL拦截器生效，打印的日志格式将变为：

2024-02-10 23:03:01.845 INFO  [dev] [XNIO-1 task-1] org.ylzl.eden.demo.infrastructure.user.database.UserMapper.selectById execute sql: SELECT id,login,email,activated,locked,lang_key,activation_key,reset_key,reset_date,created_by,created_date,last_modified_by,last_modifi    ed_date FROM demo_user WHERE id=1 (10 ms)

这种新的日志格式完全符合生产环境的要求：

1. 包含完整时间戳：便于日志检索与关联分析。
2. 输出可执行SQL：参数已直接填充到语句中，一目了然，极大提升了可读性和调试效率。
3. 记录执行耗时：直观反映SQL性能，并可通过阈值配置自动标记慢查询。

产出

团队在引入这个自定义的SQL日志组件后，在排查线上数据库相关问题时，效率得到了显著提升。更直观的日志格式让问题定位更加清晰。

更重要的是，由于消除了大量冗余的日志模板字符，日志文件的体积平均缩减了约 30%，直接降低了日志存储系统的成本压力。

本文涉及的完整实现代码已开源，感兴趣的朋友可以前往以下仓库查阅和参考：
https://github.com/shiyindaxiaojie/eden-architect/tree/main/eden-components/eden-spring-boot-starters/eden-mybatis-spring-boot-starter

如果你在微服务架构或Java性能优化方面有更多实践经验或想法，欢迎到云栈社区与广大开发者一起交流探讨。