做了多年的服务端开发排查接口耗时问题最烦的就是日志里明明有 SQL却看不清是哪个方法发的、参数是什么、到底跑了多久。尤其接手一个历史项目几十个 mapper 文件堆在一起光靠翻阅代码去猜执行链路效率太低了。所以我很早就习惯让 MyBatis 在控制台把“执行方法、执行 SQL、执行时间”三样信息一起打印出来。这个主题看着简单但翻来覆去讲的人不少真正讲透的却不多这篇就把我对 MyBatis SQL 日志的那套理解完整写出来。适合人群正在被 SQL 排查折磨的 Java 后端开发者、刚入门 MyBatis 的初学者、以及想把项目日志规范化的团队负责人。我会从原理开始给出可直接复制的配置和代码。1. 需求拆解SQL 日志到底要解决什么问题1.1 控制台日志在调试中的真实价值拿一个真实场景举例某天接口突然从 20ms 涨到 500ms你的第一反应不是打开监控大盘慢慢分析而是想在本地把请求重新打一遍。如果控制台能清楚输出这三行信息问题定位范围立刻缩小执行方法如com.example.mapper.UserMapper.getUserById告诉你这条 SQL 来自哪个 Mapper 的哪个方法。执行 SQL如SELECT id, name FROM user WHERE id 10086让你直接看到数据库真正收到的语句内容。执行时间如12 ms给你一个最基础的量化判断这条 SQL 在整体链路中占了多少耗时。这三项合在一起就是一个轻量的“SQL 观测点”。有了它排查问题时的第一步“猜”就不用了直接看输出就行。1.2 为什么优先选择控制台而非数据库日志线上数据库的慢查询日志需要权限本地开发环境访问生产库又受限而且数据库日志只能告诉你“SQL 长什么样”告诉不了你“这是哪个 Java 方法发出的”。控制台日志的优势在于零依赖、实时可见代码动了之后刷新页面立刻能看到效果这和开发调试的心流完全匹配。不过控制台打印要控制使用场景。我见过不少同事把日志级别配置一贴全环境长期开着结果生产日志文件一天涨几个 GB。所以这篇会说清楚“什么时候开、什么时候关、怎么控制开关”。1.3 三要素分别对应哪些排查场景我习惯把这三要素的用途分开看执行方法主要服务于代码定位尤其是 MyBatis 的 Mapper 接口方法名往往直接映射到 XML 里的 SQL ID看到方法名就能迅速跳转到对应代码块执行 SQL 服务于数据核对比如分页插件生成的 count SQL、动态 SQL 拼接后的条件顺序都能直接看出来执行结果与预期不符执行时间服务于性能分析不一定要精确到毫秒级关键是能区分“慢在 SQL”还是“慢在业务代码”。2. 三条实现路线先懂原理再选型2.1 MyBatis 打印 SQL 的底层机制MyBatis 自身定义了一套日志适配接口org.apache.ibatis.logging.Log运行时会根据当前 classpath 自动选择 logback、log4j2、SLF4J 等适配器。真正输出 SQL 的地方不是执行器本身而是 JDBC 层的三个代理类ConnectionLogger、PreparedStatementLogger、ResultSetLogger。当 Mapper 执行查询时MyBatis 会把PreparedStatement包一层代理在执行executeQuery()等方法前后触发日志输出也就是我们常见的这段格式 Preparing: SELECT * FROM user WHERE id ? Parameters: 1(Integer) Columns: 2 Row: 1, 张三 Total: 1这个输出格式是由 MyBatis 自己控制的日志方法级别通常要求 DEBUG 或 TRACE。控制台能不能看到完全取决于对应 Mapper 包名的 logger 级别是否被放开。2.2 三条路线的横向对比我大概整理了三种常见实现方案配置成本方法名完整SQL执行时间适用场景日志级别配置一行看不到预编译SQL参数看不到临时排查StdOutImpl一行看不到预编译SQL参数看不到MyBatis-Plus快速调试自定义Interceptor一个类能看可拼参能算项目级日志规范日志级别配置好在简单但看不到方法名和执行时间。StdOutImpl 是 MyBatis 内置的标准输出日志实现适合不想动配置文件时的临时查看。自定义拦截器成本最高但信息完整度最高这也是这篇重点讲的部分。2.3 为什么自定义拦截器更符合长期需求拦截器能拿到MappedStatement对象getId()返回的正是 Mapper 接口方法的全限定名构造BoundSql能拿到原始 SQL 和参数映射执行前后打点时间差就是耗时。相当于在 MyBatis 执行链上挂了一个旁观探针不改变原有逻辑只做记录。唯一需要花心思的是参数解析BoundSql里的参数对象可能是个 POJO、可能是 Map、可能是Param包装后的参数还可能是个简单类型。怎样安全地解析并拼回 SQL这是自定义拦截器的核心难点后面有一节专门展开。3. 实操一用日志配置快速打印预编译SQL3.1 日志框架配置与验证如果你用的是 Spring Boot最省事的方式是在application.yml里加logging: level: com.example.mapper: debugcom.example.mapper换成你自己 Mapper 接口所在的包。如果是 logback.xml 配置则写成logger namecom.example.mapper levelDEBUG/log4j2 的写法类似Logger namecom.example.mapper levelTRACE/需要注意我实测过部分 MyBatis 版本对 SQL 日志的敏感级别是 TRACE 而不是 DEBUG。如果配了 DEBUG 没效果直接改成 TRACE 再试。Spring Boot 中通过logging.level配置时写法上是debug底层映射到 logback 的 DEBUG 级别也可以用trace。配好之后启动项目随便调用一个 Mapper 方法控制台就能看到类似输出 Preparing: SELECT id, name, age FROM user WHERE id ? Parameters: 10086(Integer) Columns: 3 Row: 10086, 张三, 24 Total: 1这里最容易误解的一行是 Total它表示返回行数不是执行时间。3.2 这套方案的三个缺陷第一看不到方法名。日志输出里全是 SQL却不知道对应哪个 Mapper 方法。如果同时执行多个类似的 SQL排查效率会打折扣。第二看不到执行时间。日志级别配置的方式没有耗时输出除非你再用一个拦截器去统计或者额外写 AOP。第三预编译参数是分离的。虽然能看到Parameters行但要复制 SQL 去数据库工具里手动执行时还得自己把?替换成参数比较低效。所以这个方案适合临时快速验证不适合作为团队统一的 SQL 观测能力。4. 实操二MyBatis-Plus 与 StdOutImpl 一行配置4.1 配置位置与效果如果你用的是 MyBatis-Plus网上最流行的写法是在application.yml里加mybatis-plus: configuration: log-impl: org.apache.ibatis.logging.stdout.StdOutImpl原生 MyBatis Spring Boot 也可以这么配mybatis: configuration: log-impl: org.apache.ibatis.logging.stdout.StdOutImplStdOutImpl是 MyBatis 内置的一个Log实现类不讲日志级别、不讲 appender直接把日志打到System.out。配置之后执行 Mapper 方法时同样能看到Preparing、Parameters这些信息。4.2 注意事项用StdOutImpl有一个隐患它绕过日志框架输出不受 logback 的级别控制也不进统一日志文件。也就是说项目里如果做了日志归档SQL 日志不会出现在业务日志文件里只会在控制台。生产环境误开了这个配置日志会直接丢到标准输出运维要按日志文件排查时反而找不到。还有一个坑是同时配log-impl和自定义拦截器SQL 会被打印两份。MyBatis-Plus 的log-impl负责输出Preparing/Parameters自定义拦截器又输出一份带方法名和耗时的信息控制台瞬间刷屏。我踩过这个坑当时还疑惑为什么数据量差不多却感觉日志多了一倍。5. 实操三自定义拦截器实现“方法SQL时间”三要素5.1 拦截 Executor 的原理MyBatis 的插件机制可以拦截四大核心组件Executor、StatementHandler、ParameterHandler、ResultSetHandler。我选择拦截Executor因为它是 SQL 执行的入口。Executor上有两个关键方法需要拦截update和query。所有增删改都会走update所有查询都会走query。query方法有两套签名一套是普通查询另一套带了CacheKey和BoundSql主要用于二级缓存场景为了稳妥两个签名都要拦截。5.2 完整代码实现下面是我在实际项目中用的完整代码粘贴即可用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.session.Configuration; import org.apache.ibatis.session.ResultHandler; import org.apache.ibatis.session.RowBounds; import java.text.SimpleDateFormat; import java.util.Date; 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 { Override public Object intercept(Invocation invocation) throws Throwable { Object[] args invocation.getArgs(); MappedStatement ms (MappedStatement) args[0]; Object parameter args.length 1 ? args[1] : null; String methodId ms.getId(); BoundSql boundSql ms.getBoundSql(parameter); Configuration configuration ms.getConfiguration(); String sqlWithParams rebuildSql(configuration, boundSql); String paramsText buildParamsText(configuration, boundSql); long start System.nanoTime(); Object result invocation.proceed(); long costNanos System.nanoTime() - start; double costMs costNanos / 1_000_000.0; System.out.println( MyBatis SQL ); System.out.println(Method : methodId); System.out.println(SQL : sqlWithParams); System.out.println(Params : paramsText); System.out.println(Time : String.format(%.2f ms, costMs)); System.out.println(); return result; } private String rebuildSql(Configuration configuration, BoundSql boundSql) { String sql boundSql.getSql(); ListParameterMapping mappings boundSql.getParameterMappings(); Object parameterObject boundSql.getParameterObject(); if (mappings null || mappings.isEmpty() || parameterObject null) { return sql; } StringBuilder sb new StringBuilder(sql); int offset 0; for (ParameterMapping mapping : mappings) { String propertyName mapping.getPropertyName(); Object value getParamValue(configuration, propertyName, parameterObject); String formatted formatValue(value); int qPos sb.indexOf(?, offset); if (qPos 0) { break; } sb.replace(qPos, qPos 1, formatted); offset qPos formatted.length(); } return sb.toString(); } private Object getParamValue(Configuration configuration, String propertyName, Object parameterObject) { if (parameterObject null) { return null; } if (parameterObject instanceof Map) { Map?, ? map (Map?, ?) parameterObject; if (map.containsKey(propertyName)) { return map.get(propertyName); } if (map.containsKey(_parameter)) { return map.get(_parameter); } return map.get(param1); } if (_parameter.equals(propertyName)) { return parameterObject; } try { MetaObject metaObject configuration.newMetaObject(parameterObject); Object value metaObject.getValue(propertyName); return value ! null ? value : parameterObject; } catch (Exception e) { return parameterObject; } } private String formatValue(Object value) { if (value null) { return null; } if (value instanceof String || value instanceof Character) { return value ; } if (value instanceof Date) { return new SimpleDateFormat(yyyy-MM-dd HH:mm:ss).format(value) ; } if (value instanceof Enum) { return ((Enum?) value).name() ; } return String.valueOf(value); } private String buildParamsText(Configuration configuration, BoundSql boundSql) { ListParameterMapping mappings boundSql.getParameterMappings(); Object parameterObject boundSql.getParameterObject(); if (mappings null || mappings.isEmpty() || parameterObject null) { return []; } StringBuilder sb new StringBuilder([); for (int i 0; i mappings.size(); i) { if (i 0) { sb.append(, ); } String propertyName mappings.get(i).getPropertyName(); Object value getParamValue(configuration, propertyName, parameterObject); sb.append(propertyName).append().append(value); } return sb.append(]).toString(); } Override public Object plugin(Object target) { return Plugin.wrap(target, this); } Override public void setProperties(Properties properties) { } }5.3 参数拼接的细节说明拼接 SQL 用的是StringBuilderindexOf(?)遍历。注意第二行offset qPos formatted.length()这是为了保证多个参数替换时定位准确否则前面参数位置一变后面参数的?位置就会错位。getParamValue里优先处理 Map。MyBatis 在多参数方法配合Param时会把参数包装成ParamMap它是HashMap的子类所以走instanceof Map分支。单参数直接传 POJO 时走MetaObject反射路径。单参数是基础类型时要特别留意比如 Mapper 方法User selectByName(String name)XML 里如果写#{name}MyBatis 解析时可能取不到name属性。更稳的写法是 XML 中写#{_parameter}或者在 Mapper 方法参数上加Param(name)。5.4 两种注册方式Spring Boot 项目最简单的方式是声明一个BeanConfiguration public class MyBatisConfig { Bean public SqlLogInterceptor sqlLogInterceptor() { return new SqlLogInterceptor(); } }MyBatis Starter 会自动把Interceptor类型的 Spring Bean 注册到插件链上。如果用原生 MyBatis 的 XML 配置则在mybatis-config.xml里加plugins plugin interceptorcom.example.interceptor.SqlLogInterceptor/ /plugins多数据源场景要小心每个SqlSessionFactory都要单独注册拦截器否则只有其中一个数据源能看到日志。6. 可执行 SQL 与预编译 SQL 的区别以及开关设计6.1 拼接 SQL 只是给人看的拦截器里拼接出来的 SQL比如SELECT * FROM user WHERE id 10086只是“人类可读的还原版”。MyBatis 真正发送给数据库的是预编译的PreparedStatementSQL 里的?占位符和参数是分开传入的。数据库端拿到的是SELECT * FROM user WHERE id ?加参数10086。所以拼接 SQL 里的字符串值我习惯加单引号否则你复制到数据库客户端执行结果是完全不对的。但另一方面日志里的拼接 SQL 没有做引号转义如果字符串参数本身包含单引号展示出来可能和真实执行效果存在偏差。这也是我保留Params那一行的原因预编译 SQL 的参数列表才是真正发送给数据库的数据两者对照看就不会被误导。6.2 生产环境开关设计不管用哪种方案我都不建议长期全量打印 SQL。给拦截器加一个可控开关实际体验会好很多比如用配置中心或者系统属性控制private boolean enabled Boolean.parseBoolean(System.getProperty(sql.log.enabled, true)); private long slowThresholdMs 500;打印逻辑改成if (enabled || costMs slowThresholdMs) { // 输出日志 }这样日常开发全量开生产环境可以把开关关掉或者设置慢 SQL 阈值只有超过 500ms 才打印。既保留观测能力又不会刷屏。7. 常见问题与排查技巧实录7.1 配置了 mapper 包的 debug 级别控制台还是没 SQL优先确认三件事第一日志级别是 DEBUG但因为版本原因需要 TRACE第二配置的包名是否是 Mapper 接口所在的包而不是 Mapper XML 文件路径第三项目是否是多数据源另一个数据源的 Mapper 走了独立的 SqlSessionFactory。如果这三处都没问题再看日志框架是否配置了additivityfalse导致子 logger 的日志没有传递到 root。7.2 打印出来的 SQL 全是 ? 号看不到参数值这个是正常的PreparedStatement的日志就是这样。想直观看到参数拼接使用自定义拦截器或者直接看日志里的Parameters行。不要误以为 MyBatis 发送给数据库的 SQL 就是拼好参数的那条。7.3 执行时间统计不准有时候显示 0ms用System.currentTimeMillis()统计耗时受系统时钟影响建议用System.nanoTime()。另外Executor 层的时间包含 MyBatis 内部处理、一级缓存判断、连接获取、拦截器链等整段耗时不是纯粹的 JDBC 执行时间。如果命中二级缓存耗时可能极短甚至接近 0这属于正常现象。7.4 高并发场景下控制台输出卡顿System.out.println内部是有锁的多线程同时打印会产生锁竞争。生产环境全量打印 SQL 对性能影响很直接这也是我建议加开关的原因。7.5 拦截器里解析参数时抛反射异常常见原因是单参数传了基础类型XML 里又写了#{某属性}。解决办法单参数用#{_parameter}或者在 Mapper 方法参数上加Param。POJO 参数则直接通过MetaObject反射读取属性名即可。7.6 SQL 被打印了两次同时配置了log-impl: StdOutImpl和自定义拦截器时就会出现两份日志。只保留一种方式我一般保留自定义拦截器因为它信息更完整。8. 最后再说一个实用技巧根据我自己的经验真正有价值的不是“能打印 SQL 日志”而是“需要的时候立刻能打开不需要的时候不产生任何噪声”。把这个思路落实到代码里就是给拦截器加开关、加慢 SQL 阈值甚至可以扩展成输出到独立的日志文件和监控平台。这样一个小工具就不会局限于本地调试而是能伴随项目长期存在。