MyBatis SQL日志拦截器实战：打印执行方法、真实SQL与耗时

写这篇东西的起因很简单：前段时间排查线上慢SQL，发现项目里用的是最原始的日志配置——SQL有时打印有时不打印，打印出来的一坨还带参数占位符，根本看不出真实执行语句，更不要提耗时。所以花了点时间把 MyBatis 的日志机制彻底过了一遍，又动手写了一个拦截器，把“执行方法、执行SQL、执行时间”三要素一次性打到控制台。这篇文章就把整个思路、代码、踩坑过程都整理出来，给同样被SQL日志折腾过的同学一份可以直接抄作业的参考。

1. 为什么需要自定义SQL日志打印：原生方案到底输在哪

1.1 MyBatis自带日志的两种形态：你见过却没留意的细节

MyBatis 本身不是没有打印SQL的能力。你只要在配置文件里把 log-impl 指到 StdOutImpl，然后执行一条查询，控制台立刻就能看到类似这样的输出：

==> Preparing: SELECT * FROM user WHERE id = ? ==> Parameters: 1(Long) <== Columns: id, name, age <== Row: 1, 张三, 25 <== Total: 1

这个输出很经典，但它有两个让我难受的点。第一，Preparing 那行输出的永远是带?占位符的模板SQL，我要把它复制到数据库客户端里跑，还得手动把参数填回去，多一步不说，参数一多还容易填错位置。第二，整段输出里没有任何毫秒级耗时信息，偶尔有<== Total: 1这种行数反馈，但到底这条SQL跑了 5ms 还是 500ms，完全看不出来。

还有一种形态是配合 Slf4j 或 Log4j2 这类日志框架，通过mapper包名级别的DEBUG日志输出同样的内容。这种方式的好处是日志可以统一走框架的格式化和归档策略，坏处依然存在：SQL 模板和参数分离，没有耗时统计。本质上就是换了个输出通道，内容没有本质变化。

1.2 原生日志和拦截器自定义打印的效果对比

既然目标是把“执行方法、执行SQL、执行时间”三要素一次看清楚，那我直接列一下原生方案和自定义拦截器方案在控制台信息上的差异：

看到这个对比，很多人会直接跳进拦截器方案。但我想说，如果你只是临时调试，原生日志足够；如果你是长期开发、维护、做慢SQL排查，拦截器方案才是真正值得投入的方向。下面的内容，我会把从原生配置到拦截器实现的完整路径都走一遍。

2. 零门槛先做起来：打开MyBatis自带SQL日志

2.1 配置log-impl的三种方式与适配器原理

MyBatis 的 SQL 日志不是天然打开的，它内部通过org.apache.ibatis.logging.LogFactory做了一层日志适配，启动时会按照固定的优先级尝试查找可用的日志实现：Slf4j、Apache Commons Logging、Log4j2、Log4j、JdkLogging、StdOut。找到哪个就用哪个，所以如果你项目里同时存在多个日志框架，MyBatis 会自动选一个，这个“自动”有时候会选到不是你预期的那一个，造成日志“看起来没生效”。

手动指定日志实现，最直接的方式是改 MyBatis 的configuration：

<configuration> <settings> <setting name="logImpl" value="STDOUT_LOGGING"/> </settings> </configuration>

如果你用的是 Spring Boot 且引入了mybatis-spring-boot-starter，在application.yml里写：

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

如果用的是mybatis-plus-boot-starter，写法是：

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

这两种方式指定的是同一个类StdOutImpl，效果也是完全一致的：直接把日志打到System.out。对于本地开发来说，这是最快能看到SQL的路径。

2.2 日志框架级别与mapper包级别设置：这一步最容易被忽略

很多人在 Spring Boot 项目里把 log-impl 配成 Slf4j，却发现 SQL 日志还是不出来，原因基本都落在日志级别上。MyBatis 的 Mapper 接口和MappedStatement所属的 logger 名称通常就是你的 mapper 接口全限定名，例如com.example.mapper.UserMapper。只有这个 logger 的级别达到DEBUG，MyBatis 的PreparedStatementLogger才会真正输出 Preparing 和 Parameters。

所以，如果你用的是slf4j+logback，不仅要在 MyBatis 这边指定SLF4J作为日志实现，还要在logback.xml里把 mapper 包整体调成 DEBUG：

<logger name="com.example.mapper" level="DEBUG"/>

如果你不想按包控制，也可以直接调整全局日志级别到 DEBUG，但那样会把框架内部海量的 DEBUG 日志也带出来，噪音太大。实践中我更推荐只对 mapper 包开 DEBUG，日志量可控，定位问题又足够。

日志顺序问题也需要提一下：log-impl指定的是 MyBatis 内部通过哪个日志门面输出，而logback.xml控制的是门面之下的输出级别。两者必须配合，一个指定通道，一个放行级别，少一个都看不到日志。

2.3 知识补充：StdOutImpl与Slf4jImpl的差异

为了不让大家配置时一脸懵，这里把两个最常用的实现拆开讲一下。StdOutImpl是最直白的实现，它不依赖任何日志框架，直接把内容System.out.println到控制台。好处是零配置、立刻见效，坏处是不能按文件输出、不能级别过滤、生产环境如果忘了关，日志会直接混进应用标准输出流，增加排查成本。

Slf4jImpl则意味着 MyBatis 产生的日志会交给 Slf4j 门面，再由门面路由到 Logback 或 Log4j2。这种方式的优势在于所有日志能统一格式、统一归档、统一级别管理，生产环境比较友好。但前提是项目里必须存在可用的 Slf4j 绑定实现，否则 MyBatis 会在启动时抛出找不到日志实现的异常，或者静默切到下一个可用实现。

所以在本地快速验证、临时排查时，我建议用 StdOutImpl；一旦进入持续开发阶段，尽早切换到 Slf4j 门面，配合包级 DEBUG 配置，这样长期来看更干净。

3. 自己动手：基于Interceptor实现执行方法、SQL、耗时打印

3.1 拦截器选型：为什么拦Executor而不是StatementHandler

MyBatis 的插件机制只作用于四个核心对象：Executor、StatementHandler、ParameterHandler、ResultSetHandler。在这四个对象里，如果我关心的是“这条SQL最终执行完总共花了多少毫秒”，那么拦截Executor是最合适的。

原因很简单：Executor是 MyBatis 执行链路的最外层门面，从SqlSession的select/insert/update/delete进来之后，先走缓存判断、再走StatementHandler创建语句、ParameterHandler绑定参数、ResultSetHandler处理结果集，最后再回到Executor。也就是说，在Executor的query/update方法入口处打点，开始计时，等invocation.proceed()返回之后计时结束，这个耗时覆盖了完整的一条 SQL 从参数解析到结果集映射的全过程。

如果你只拦截StatementHandler的prepare或query，那只能拿到 JDBC 层面语句执行的局部耗时，绑定参数、结果集映射这些环节的耗时都会漏掉。从排查慢SQL的角度来说，全链路耗时才是业务方真正感知的耗时，拦截Executor也最贴近“这条SQL执行了多久”的直觉。

3.2 拦截器签名与兼容性问题，MyBatis 3.x的坑

写拦截器之前，有一项绕不开的功课：确定拦截的Executor方法的准确签名。不同 MyBatis 版本里，Executor.query存在两种策略。在 MyBatis 3.4 及之后的版本中，Executor接口的 query 方法通常被声明成两种重载：

第一种是四个参数：

query(MappedStatement ms, Object parameter, RowBounds rowBounds, ResultHandler resultHandler)

第二种是六个参数：

query(MappedStatement ms, Object parameter, RowBounds rowBounds, ResultHandler resultHandler, CacheKey cacheKey, BoundSql boundSql)

其中六个参数的方法主要在二级缓存命中场景中使用，如果拦截器签名里漏掉它，某些查询走二级缓存时不会经过你拦截的方法，导致部分SQL日志缺失。

update方法则稳定得多：

update(MappedStatement ms, Object parameter)

所以在@Intercepts注解里，我同时声明了三个@Signature，分别覆盖两个 query 重载和一个 update。主要代码如下：

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

这个写法兼容了 MyBatis 3.x 的主流版本。万一你的项目还停留在老旧的 3.2、3.3 时代，那么Executor.query很可能只有四个参数的那个重载，没有六个参数版本，拦截器里多写了会直接启动报错。遇到这种情况，删掉六个参数的@Signature即可。

3.3 完整代码实现：获取执行方法、替换参数、统计耗时

先给出一份可以直接落地使用的完整拦截器实现。核心逻辑分成三块：从MappedStatement取执行方法、从BoundSql取真实SQL并做参数替换、在proceed()前后统计耗时。

package com.example.interceptor; import org.apache.ibatis.cache.CacheKey; import org.apache.ibatis.executor.Executor; import org.apache.ibatis.mapping.BoundSql; import org.apache.ibatis.mapping.MappedStatement; import org.apache.ibatis.mapping.ParameterMapping; import org.apache.ibatis.plugin.Interceptor; import org.apache.ibatis.plugin.Intercepts; import org.apache.ibatis.plugin.Invocation; import org.apache.ibatis.plugin.Plugin; import org.apache.ibatis.plugin.Signature; import org.apache.ibatis.reflection.MetaObject; import org.apache.ibatis.reflection.SystemMetaObject; import org.apache.ibatis.session.ResultHandler; import org.apache.ibatis.session.RowBounds; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import java.util.List; import java.util.Map; import java.util.Properties; @Intercepts({ @Signature(type = Executor.class, method = "update", args = {MappedStatement.class, Object.class}), @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}), @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class, CacheKey.class, BoundSql.class}) }) public class SqlLogInterceptor implements Interceptor { private static final Logger log = LoggerFactory.getLogger(SqlLogInterceptor.class); @Override public Object intercept(Invocation invocation) throws Throwable { MappedStatement ms = (MappedStatement) invocation.getArgs()[0]; Object parameter = invocation.getArgs()[1]; BoundSql boundSql = ms.getBoundSql(parameter); String executableSql = buildExecutableSql(boundSql, parameter); String methodId = ms.getId(); long start = System.currentTimeMillis(); try { return invocation.proceed(); } finally { long cost = System.currentTimeMillis() - start; log.info("[SQL执行] method={}, sql={}, cost={}ms", methodId, executableSql, cost); } } private String buildExecutableSql(BoundSql boundSql, Object parameter) { String sql = boundSql.getSql().replaceAll("\\s+", " ").trim(); List<ParameterMapping> parameterMappings = boundSql.getParameterMappings(); if (parameterMappings == null || parameterMappings.isEmpty()) { return sql; } for (ParameterMapping mapping : parameterMappings) { Object value = getParameterValue(parameter, mapping.getProperty()); sql = sql.replaceFirst("\\?", toSqlString(value)); } return sql; } private Object getParameterValue(Object parameterObject, String propertyName) { if (parameterObject == null) { return "null"; } if (parameterObject instanceof Map) { return ((Map<?, ?>) parameterObject).get(propertyName); } MetaObject metaObject = SystemMetaObject.forObject(parameterObject); if (metaObject.hasGetter(propertyName)) { return metaObject.getValue(propertyName); } // 单参数简单类型：参数对象本身就是值 if (isSimpleType(parameterObject)) { return parameterObject; } return "null"; } private boolean isSimpleType(Object obj) { return obj instanceof CharSequence || obj instanceof Number || obj instanceof Boolean || obj instanceof java.util.Date || obj instanceof Enum; } private String toSqlString(Object value) { if (value == null) { return "null"; } if (value instanceof CharSequence || value instanceof java.util.Date || value instanceof Enum) { return "'" + value + "'"; } return String.valueOf(value); } @Override public Object plugin(Object target) { return Plugin.wrap(target, this); } @Override public void setProperties(Properties properties) { } }

这段代码里，最需要讲清楚的是参数替换逻辑。MyBatis 执行 SQL 时，BoundSql.getSql()拿到的是带?的预编译模板，每个?对应ParameterMapping列表中的一项。所以我遍历parameterMappings，逐个把?替换成实际参数值。

参数值的获取我用了MetaObject，它兼容 POJO 和 Map 两类常见场景。如果参数是@Param("id") Long id，MyBatis 会把参数包装成一个ParamMap，里面的 key 同时包含注解名和param1这类索引名，Map.get(propertyName)就能命中。如果参数是单个简单类型，ParameterMapping.getProperty()取到的可能是一个无意义的占位名称，MetaObject.hasGetter返回 false，这时直接判断isSimpleType并把参数对象本身作为值，能覆盖大多数场景。

耗时统计放在finally块里是故意的。哪怕 SQL 执行抛了异常，日志也能打出耗时和SQL，方便排查问题SQL。如果你只关心成功执行的日志，把打印语句挪到try块内、return之前即可，这个看个人偏好。

3.4 注册拦截器的三种方式与生效确认方法

拦截器写完后，必须让 MyBatis 知道它的存在。根据项目形态不同，有三种常见注册方式。

如果是纯 MyBatis + mybatis-config.xml，在<plugins>节点下注册：

<plugins> <plugin interceptor="com.example.interceptor.SqlLogInterceptor"/> </plugins>

如果是 Spring Boot + mybatis-spring-boot-starter，最省事的做法是把它声明成一个 Spring Bean。mybatis-spring-boot-starter 启动时会自动去应用上下文里找所有实现了Interceptor接口的 Bean，并注册到 SqlSessionFactory：

@Configuration public class MybatisConfig { @Bean public SqlLogInterceptor sqlLogInterceptor() { return new SqlLogInterceptor(); } }

如果你已经在拦截器类上加了@Component，其实也能生效，原理同上。但为了配置可读性，我习惯单独建一个配置类。

第三种是编程式注册，在自定义SqlSessionFactory时手动 add 进去：

SqlSessionFactoryBean factoryBean = new SqlSessionFactoryBean(); factoryBean.setPlugins(new Interceptor[]{new SqlLogInterceptor()});

这种写法多用于自定义数据源、自定义工厂的复杂场景，普通项目用前两种就够了。

生效确认很简单：执行任意一条 SQL，控制台看到[SQL执行] method=..., sql=..., cost=...ms，说明拦截器已被加载。如果没看到，优先检查两点：确认配置类被 Spring 扫描到、确认方法签名和实际 MyBatis 版本匹配。

3.5 日志格式与脱敏：该打印哪些、不该打印哪些

日志能打出来之后，下一步就要想清楚“打什么”和“不打什么”。

我个人推荐的日志格式是：

[SQL执行] method=com.example.mapper.UserMapper.selectUserById, sql=SELECT * FROM user WHERE id = 1, cost=3ms

一行之内把执行方法、真实SQL、耗时全部呈现出来，搜索时用 grep 直接定位，方便把它接到日志采集系统里做后续分析。如果项目里 SQL 普遍较长，也可以把 sql 单独放一行，但这样日志采集时解析多行记录略麻烦，我是更倾向于单行格式。

脱敏是很容易被忽略的点。直接把参数拼进 SQL 打到日志，意味着用户名、手机号、身份证这类敏感字段会明文落盘。在开发环境当然无所谓，但生产环境如果开这个日志，建议在拦截器里做一层策略：敏感字段用*替换，或者干脆只打印 SQL 模板、不拼参数。我自己在研发环境里是全部打印，但同一套代码部署到生产时会通过配置中心把打印开关关掉，只留慢SQL阈值告警。这个开关后面会提到。

4. 实战中常见的坑与排查实录

4.1 什么日志都没有，八成是这几个原因

我见过太多次“配置了 log-impl 但控制台什么都没打”的场景，排查的时候按顺序检查下面几项，基本能覆盖 90% 的原因。

第一，确认 MyBatis 日志实现被正确指定。如果通过application.yml配置，要注意前缀是mybatis还是mybatis-plus，写错前缀等于没配置。第二，确认日志级别放行。用 Slf4j 时，mapper 包级别必须是 DEBUG，很多日志框架默认 info 级别，DEBUG 日志直接被过滤掉。第三，确认项目里是否存在多个日志门面实现导致 MyBatis 适配器选偏了。可以先临时指定STDOUT_LOGGING，如果马上能看到 SQL，说明是门面路由问题，再回头调日志框架配置。第四，检查是否用了低版本 MyBatis 且 SQL 走的是二级缓存分支，这时候拦截器如果没有匹配对应方法签名，部分 SQL 会漏打，看起来像日志丢失。

一个更隐蔽的场景是：MyBatis 的日志适配器初始化发生在SqlSessionFactory构建阶段，如果你在mybatis-config.xml里配置logImpl，但实际创建 SqlSessionFactory 时没有加载这份配置文件，那配置会静默失效。遇到这种情况，直接在SqlSessionFactoryBean.setConfiguration()里显式指定 Configuration 对象，排查更直观。

4.2 拦截器不生效、日志重复打印、动态SQL参数对不上

拦截器不生效，优先级最高的怀疑对象就是@Intercepts签名。很多人只拦截了四个参数的query，实际项目里 MyBatis 不少调用会走六个参数的query，结果日志时有时无，看起来就像“不生效”。我的建议是一开始就把三个签名全部声明，确保覆盖完整。

日志重复打印的原因则常见于“原生日志 + 自定义拦截器”同时开启。你配置了 StdOutImpl，控制台本来就有 Preparing 和 Parameters，再叠加拦截器输出，一行 SQL 至少重复两遍。解决方式也很简单：拦截器方案稳定后，把log-impl改成NO_LOGGING，或者把 mapper 包级别从 DEBUG 调回 INFO，只保留拦截器一路输出。

动态SQL参数对不上是拦截器方案里最麻烦的坑。比如<foreach>生成的 SQL，参数映射里会出现__frch_item_0这种特殊占位名，从parameterObject里直接按这个名字取值经常会得到 null。我的处理方式是：遇到__frch_前缀的映射名，说明是动态SQL的循环参数，可以直接返回参数对象本身的值，或者干脆在这里不拼参，输出 SQL 模板加一个参数列表，避免把错误信息误导到日志里。参数替换是锦上添花的功能，如果某些极端场景替换不了，退回显示模板加参数反而更可靠。

4.3 对性能到底有多大影响，生产环境怎么取舍

每个第一次接触拦截器的人都会问这个问题：每次SQL执行都做反射调用和字符串替换，会不会拖慢系统？

我的实测结论是：只有在 QPS 极高的场景下影响才需要认真对待。一次拦截的额外开销主要是ms.getBoundSql(parameter)的调用、SystemMetaObject.forObject的反射包装、还有字符串replaceFirst。普通单条 SQL 场景下，这些操作大概在几十微秒级别，相比一次真实数据库查询动不动几毫秒的性能，占比并不大。但如果你的系统单机 QPS 上万，且每条 SQL 都打全量日志，日志 IO 本身反而可能成为瓶颈，拦截器自身的开销就得往后排了。

所以生产环境的取舍建议是：把“全量打印”和“慢SQL打印”分开对待。全量打印用开关控制，默认关闭；慢SQL打印保留，设定一个阈值，当cost超过阈值时才打印，这样既能保留性能问题现场，又不至于日志爆炸。实现上也很简单，在拦截器里加一个slowThresholdMs字段，日志级别根据阈值动态切换：

private long slowThresholdMs = 300; if (cost >= slowThresholdMs) { log.warn("[慢SQL] method={}, sql={}, cost={}ms", methodId, executableSql, cost); } else { log.debug("[SQL执行] method={}, sql={}, cost={}ms", methodId, executableSql, cost); }

这个阈值建议通过配置注入而不是写死在代码里，不同环境、不同业务模块可以灵活调整。再配合采样率，比如只在流量较低的时间段开启全量打印，就能在排查性能和保持系统稳定之间找到一个比较舒服的平衡。

拦截器这套东西我用了很久，最大的体会是：平庸的日志方案折磨人，但过度设计的日志方案同样折磨人。先从原生日志跑通链路，再落到拦截器把三要素打印出来，最后根据环境控制打印开关和慢SQL阈值，这条路对我来说是最稳的。如果你也想在项目里加类似的 SQL 执行信息输出，可以照着这篇文章的代码先落一版，跑一段时间你自然会发现哪些字段该加、哪些格式该改——日志这种东西，永远是先跑起来才有资格谈优化。