1. 为什么默认配置下控制台看不到SQL：日志门面与MyBatis的耦合关系

很多刚接触Spring Boot + MyBatis的同学都会有一个疑问：为什么我在application.yml里写了mybatis.configuration.log-impl: org.apache.ibatis.logging.stdout.StdOutImpl，控制台确实打印SQL了，但打印出来的信息只有Preparing: select * from user where id = ?和Parameters: 1(String)，完全没有执行方法、执行时间这些关键信息？

要搞清楚这个问题，得先明白MyBatis的日志体系是怎么设计的。MyBatis自己并没有实现日志框架，它内部定义了一套日志抽象层，通过org.apache.ibatis.logging.Log接口来统一适配市面上主流的日志组件——SLF4J、Log4j2、Logback、JDK Logging、Apache Commons Logging，以及它自己内置的StdOutImpl（标准输出实现）。

当你设置了log-impl为StdOutImpl时，MyBatis确实会把SQL语句、参数、查询结果直接打到控制台。但这里有个关键细节：StdOutImpl的打印逻辑是固定的，它只输出Preparing、Parameters、Total等几行固定格式的内容。执行方法名、执行耗时这些信息，MyBatis的日志抽象层压根就没设计进去。所以无论你怎么调整日志级别，用默认的StdOutImpl永远看不到完整信息。

那用Logback或者Log4j2作为日志实现就能看到执行方法了吗？也不完全。SLF4J接入MyBatis之后，日志输出是按照Mapper接口的全限定名作为Logger名称的。比如你的Mapper接口是com.example.mapper.UserMapper，那么SQL日志会出现在名为com.example.mapper.UserMapper的Logger下。你把该Logger的级别调到DEBUG，确实能看到SQL，但看到的还是Preparing、Parameters、Total这老三样，执行方法名依然没有。

这里要说明一下，MyBatis官方其实提供了org.apache.ibatis.logging.jdbc.BaseJdbcLogger这样一个底层的JDBC日志封装，它负责拦截PreparedStatement的创建、参数设置、查询执行等环节。但在默认实现中，它没有记录调用Mapper方法名的能力。Mapper方法名和SQL语句之间的对应关系，MyBatis是在解析阶段就建立好的（通过MapperProxy调用SqlSession的selectOne/selectList/insert/update/delete方法），但这一层调用链路没有暴露给日志系统。

所以结论很直接：想拿到执行方法、执行SQL、执行时间三件套，单靠配置是不行的，必须自己做一层拦截或者扩展。

我在早期项目里也纠结过这个问题，翻过MyBatis源码，试过各种配置组合，最后发现最干净、最可控的方案是自己写一个MyBatis的Interceptor插件。这个方案不侵入业务代码，只需要注册一个拦截器，就能拿到完整的方法签名、SQL语句、执行耗时。后面我会详细展开实现过程。

2. 先走捷径：MyBatis-Plus和P6Spy能解决一半问题吗

在自研Interceptor之前，有必要先聊聊市面上现成的工具。很多人听说过MyBatis-Plus自带的SQL打印插件，也有人用P6Spy、Jpau等第三方JDBC代理工具来打印SQL。这些方案各有特点，但都有明显的边界。

2.1 MyBatis-Plus的SQL分析插件

如果你的项目用的是MyBatis-Plus，那么配置SQL打印其实非常简单。MyBatis-Plus提供了一个PaginationInnerInterceptor，同时还有一个专门用于SQL分析的PerformanceInterceptor（在3.x版本中改名为MybatisPlusInterceptor配合PaginationInnerInterceptor使用）。

在旧版MP中，配置方式是这样的：

@Bean public MybatisPlusInterceptor mybatisPlusInterceptor() { MybatisPlusInterceptor interceptor = new MybatisPlusInterceptor(); interceptor.addInnerInterceptor(new PaginationInnerInterceptor(DbType.MYSQL)); return interceptor; }

配合application.yml中把Mapper接口的日志级别调到DEBUG：

logging: level: com.example.mapper: debug

这样MyBatis-Plus会把SQL、参数、执行结果都打出来，但格式依然受限于MyBatis默认的日志输出格式。更重要的是，MP的SQL分析插件更侧重于慢SQL告警和分页优化，比如你可以设置maxLimit防止全表查询，可以通过PerformanceInterceptor的maxTime属性来输出超过指定阈值的SQL。但执行方法名的输出，MP也没有做。

2.2 用P6Spy打印完整SQL

P6Spy的思路和MyBatis完全不同，它是在JDBC层面做代理。P6Spy会拦截所有经过JDBC的SQL请求，重新拼接参数后输出完整可执行的SQL语句（MyBatis默认打印的是带?占位符的预编译SQL，很多同学嫌它不能直接复制到数据库执行，P6Spy恰好解决了这个问题）。

配置P6Spy需要这几步：

1. 引入依赖

<dependency> <groupId>p6spy</groupId> <artifactId>p6spy</artifactId> <version>3.9.1</version> </dependency>

2. 修改数据源URL，加上p6spy前缀

spring.datasource.url: jdbc:p6spy:mysql://localhost:3306/demo_db spring.datasource.driver-class-name: com.p6spy.engine.spy.P6SpyDriver

3. 配置spy.properties文件

appender=com.p6spy.engine.spy.appender.Slf4JLogger logMessageFormat=com.p6spy.engine.spy.appender.CustomLineFormat customLogMessageFormat=%(currentTime) | took %(executionTime) ms | %(sql)

这样控制台就会输出每一条SQL的执行耗时和完整的参数绑定后的SQL。但注意，P6Spy是一个JDBC层级的通用工具，它并不知道MyBatis的存在，所以它输出的SQL信息里不包含Mapper方法名。而且P6Spy对批量操作的支持不算好，批量插入时它会打印很多重复的预编译SQL，日志量爆炸，需要额外去重。

2.3 结论：还是得自己动手

综合来看，MyBatis-Plus插件拿不到执行方法名，P6Spy也拿不到，而且P6Spy还引入了额外的代理层，对性能有一定损耗。真正能同时拿到"执行方法 + 执行SQL + 执行时间"的方案，只有基于MyBatis的Interceptor机制去自定义实现。

这里补充说明一下，问题核心在于MyBatis的Invocation对象里可以通过getMethod()拿到Mapper方法对象，通过getArgs()拿到方法参数，而SQL语句则藏在BoundSql里。这四个东西凑齐了，打印三件套就是水到渠成的事。

3. 自研Interceptor方案：完整实现一个SQL日志打印插件

说干就干。下面是我在实际项目中落地的一个MyBatis Interceptor实现，代码不复杂，但细节不少。你直接复制到项目里，注册为Bean，就能用。

3.1 核心代码实现

先定义拦截器类：

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.*; 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 org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.stereotype.Component; import org.springframework.util.StopWatch; import java.text.SimpleDateFormat; import java.util.Date; import java.util.List; 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}) }) @Component public class SqlLogInterceptor implements Interceptor { private static final Logger log = LoggerFactory.getLogger(SqlLogInterceptor.class); private static final ThreadLocal<SimpleDateFormat> DATE_FORMAT = ThreadLocal.withInitial(() -> new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS")); @Override public Object intercept(Invocation invocation) throws Throwable { StopWatch stopWatch = new StopWatch(); stopWatch.start(); Object result = invocation.proceed(); stopWatch.stop(); // SQL执行完之后，统一收集信息并打印 printSqlLog(invocation, stopWatch.getTotalTimeMillis()); return result; } private void printSqlLog(Invocation invocation, long executeTime) { try { MappedStatement mappedStatement = (MappedStatement) invocation.getArgs()[0]; Object parameter = invocation.getArgs().length > 1 ? invocation.getArgs()[1] : null; String methodName = getMapperMethodName(mappedStatement); String sql = getSql(mappedStatement, parameter); String jdbcUrl = getJdbcUrl(mappedStatement.getConfiguration()); String timeStr = DATE_FORMAT.get().format(new Date()); log.info("\n================== MyBatis SQL 执行信息 ==================\n" + "执行时间: {}\n" + "执行方法: {}\n" + "执行耗时: {} ms\n" + "数据库连接: {}\n" + "执行SQL:\n{}\n" + "======================================================", timeStr, methodName, executeTime, jdbcUrl, sql); } catch (Exception e) { // 拦截器本身不能影响业务逻辑，打印失败只记录警告 log.warn("SQL日志打印失败", e); } } private String getMapperMethodName(MappedStatement mappedStatement) { String id = mappedStatement.getId(); // id的格式是 com.example.mapper.UserMapper.selectById， // 只保留最后的methodName，完整的可以单独提取 String className = id.substring(0, id.lastIndexOf('.')); String methodName = id.substring(id.lastIndexOf('.') + 1); return className + "#" + methodName + "()"; } private String getSql(MappedStatement mappedStatement, Object parameter) { BoundSql boundSql = mappedStatement.getBoundSql(parameter); Configuration configuration = mappedStatement.getConfiguration(); return getRealSql(configuration, boundSql); } private String getRealSql(Configuration configuration, BoundSql boundSql) { Object parameterObject = boundSql.getParameterObject(); List<ParameterMapping> parameterMappings = boundSql.getParameterMappings(); String sql = boundSql.getSql().replaceAll("[\\s]+", " "); if (parameterMappings.isEmpty() || parameterObject == null) { return sql; } // 将 SQL 中的 ? 逐个替换为实际参数值 for (ParameterMapping parameterMapping : parameterMappings) { String propertyName = parameterMapping.getPropertyName(); Object value = getValueByPropertyName(parameterObject, propertyName); sql = sql.replaceFirst("\\?", "'" + formatParameter(value) + "'"); } return sql; } private Object getValueByPropertyName(Object parameterObject, String propertyName) { if (parameterObject == null) { return null; } try { MetaObject metaObject = configuration.newMetaObject(parameterObject); return metaObject.getValue(propertyName); } catch (Exception e) { return "**无法解析**"; } } private String formatParameter(Object value) { if (value == null) { return "null"; } if (value instanceof String || value instanceof Character || value instanceof Date) { return String.valueOf(value); } return String.valueOf(value); } private String getJdbcUrl(Configuration configuration) { // 从Configuration的Environment中读取数据源信息 try { javax.sql.DataSource dataSource = configuration.getEnvironment().getDataSource(); if (dataSource != null) { // 通过反射拿DataSource的实现类里的url java.lang.reflect.Field field = getUrlField(dataSource.getClass()); if (field != null) { field.setAccessible(true); Object url = field.get(dataSource); if (url != null) { return url.toString(); } } } } catch (Exception e) { // ignore } return "未知"; } private java.lang.reflect.Field getUrlField(Class<?> clazz) { while (clazz != null) { try { java.lang.reflect.Field field = clazz.getDeclaredField("url"); return field; } catch (NoSuchFieldException e) { clazz = clazz.getSuperclass(); } } return null; } @Override public Object plugin(Object target) { // 只拦截Executor类型的目标对象 return Plugin.wrap(target, this); } @Override public void setProperties(Properties properties) { // 可以读取properties配置，比如是否打印慢SQL阈值 } }

3.2 代码里藏着的几个关键细节

这段代码有几个容易踩坑的地方，我逐个拆开来说。

第一个坑：拦截方法签名必须写对。MyBatis的Executor接口里，query方法有两个重载版本。老版本只有4个参数的那个，新版本增加了带CacheKey和BoundSql的6参数版本。如果你只拦截了4参数版本，当MyBatis执行二级缓存查询时会走6参数那条路，你的拦截器就不会生效。所以必须两个query签名都声明。

第二个坑：StopWatch的start必须放在invocation.proceed()之前。很多人习惯先把proceed()的结果存起来再算时间，这样算出来的时间其实包含了后续清理资源的过程，不完全准确。用StopWatch把计时逻辑包在核心方法调用上，结果最干净。

第三个坑：参数替换逻辑要处理好。MyBatis的BoundSql.getSql()返回的是带?占位符的原始SQL，如果你只是打印这个SQL，开发者没法直接把它复制到Navicat里执行。我在代码里做了参数绑定替换，把每个?替换成实际的参数值。这里用正则replaceFirst一个个替换，要注意如果参数值本身也包含?字符（比如一个字符串内容是"what?"），就会替换错位。更稳妥的做法是先占位再统一替换，但对于大多数业务场景，这个简单版本已经够用。

第四个坑：获取JDBC URL用了反射。不同的数据库连接池（HikariCP、Druid、Tomcat JDBC Pool）持有URL的字段名不一样。HikariCP的字段是jdbcUrl，Druid的是url，我上面的反射代码默认找url字段，遇到HikariCP就会拿不到。如果你想兼容多种连接池，建议多看一层。不过话说回来，打印数据库连接信息只是辅助排查用的，拿不到也不影响主流程。

这里我再补充一个事务的场景。当你在一个事务里执行了多条SQL，这些SQL是在同一个数据库连接上执行的。如果你在事务方法里启动了MyBatis的批量操作或者多次查询，拦截器会分别打印每一条SQL的日志，但它们共享同一条数据库连接。这个信息对于排查连接池泄漏、死锁问题非常有用，所以我在日志里加了数据库连接地址一栏。

3.3 注册拦截器并验证效果

在Spring Boot项目中，最简单的做法就是把这个类加上@Component注解，MyBatis在初始化时会自动扫描到并且注册。如果你的项目是多数据源，建议使用@Bean方式手动注册，指定给某个特定的SqlSessionFactory：

@Configuration public class MybatisConfig { @Bean public ConfigurationCustomizer mybatisConfigurationCustomizer() { return configuration -> { SqlLogInterceptor interceptor = new SqlLogInterceptor(); configuration.addInterceptor(interceptor); }; } }

启动项目后，随便调用一个Mapper方法，控制台输出效果如下：

================== MyBatis SQL 执行信息 ================== 执行时间: 2024-11-16 11:23:45.123 执行方法: com.example.mapper.UserMapper#selectUserList() 执行耗时: 23 ms 数据库连接: jdbc:mysql://localhost:3306/demo_db?useSSL=false&characterEncoding=utf8 执行SQL: SELECT id, username, email, create_time FROM user WHERE status = 'ACTIVE' AND id IN (1, 2, 3) ======================================================

这个方法名、SQL、耗时三件套一眼就能看清，排查问题效率直接上一个台阶。

3.4 通过方法名精确过滤SQL日志

拿到方法名还有一个隐藏的好处，就是可以按方法维度来过滤日志。举个例子，某个页面接口调用了七八个Mapper方法，执行时间加起来有200ms，你想知道到底哪个方法慢。如果你的日志里只有SQL没有方法名，你只能靠SQL内容反推；有了方法名之后，直接搜索方法名即可快速定位。

更进一步，你可以在拦截器里加一个白名单/黑名单机制：

// 黑名单：不打印ResultMap映射相关的方法调用 private static final List<String> IGNORED_METHODS = Arrays.asList("selectCount"); // 白名单：只打印关键业务方法 private static final List<String> WATCH_METHODS = Arrays.asList("updateUser", "insertBatch");

然后在printSqlLog里做匹配过滤。这个功能在实际项目中很有用——开发阶段全量打印，上线后只保留慢查询或指定方法的日志，避免日志量过大。

4. 从打印SQL到看清性能：慢SQL定位与执行耗时剖析

工具做出来了，更重要的是怎么用它解决实际问题。我在公司项目里落地这个拦截器之后，最直接的收益就是慢SQL定位从"靠猜"变成了"看图说话"。

4.1 执行耗时的三个层次

要理解执行耗时，得先分清SQL耗时的构成。一次完整的数据库操作耗时可以分为三个阶段：

1. 网络传输耗时：客户端到数据库服务器之间的网络往返延迟。每次请求数据，都要经过TCP连接、SSL握手（如果开启）、数据包传输。如果数据库和应用部署在两台机器上，这个耗时通常是稳定的一两毫秒，但如果跨机房访问，可能飙升到几十毫秒。

2. 数据库执行耗时：数据库引擎真正执行SQL的时间，包括解析SQL、生成执行计划、扫描数据、回表查数据等。这个耗时受索引、数据量、锁竞争影响最大。

3. JDBC驱动与MyBatis的解析耗时：MyBatis把结果集映射成Java对象的时间，以及JDBC驱动的编解码时间。

我的Interceptor拿到的耗时是整个invocation.proceed()的耗时，它包含了上面全部三部分，而不仅仅是数据库执行时间。所以如果你发现某条SQL打印出来耗时为50ms，但这条SQL在数据库客户端里执行只要5ms，那么剩余45ms很可能花在应用层到数据库的网络传输，或者MyBatis的结果映射上。

怎么进一步区分是哪一层的耗时？我分享一个实操技巧：直接看SQL对应方法返回的结果集大小。如果select返回几百条数据，耗时偏高大概率是数据库执行慢或者网络传输慢；如果返回上万条数据，耗时偏高大概率是MyBatis结果映射慢。之前我遇到过一个项目，一条SQL查询出来的数据有5万多行，每次执行耗时稳定在180ms，但这条SQL本身只有40ms。后来排查发现，问题出在resultMap里配置了多个嵌套子查询（N+1查询），MyBatis在映射时又发起了几百次额外的查询请求。这种情况光看SQL日志看不出来，还得结合日志里同一次请求出现的大量重复SQL语句才能推断出来。

4.2 慢SQL阈值的实践经验

拦截器做好之后，下一个常规操作就是给慢SQL加告警。我在setProperties里预留了慢SQL阈值配置，但实际项目里我更推荐按时间段来统计，而不是设一个固定的阈值。

举个例子：白天高峰期查询用户列表，SQL耗时80ms可能还没问题，因为并发高、锁竞争激烈；但凌晨低峰期同样的SQL耗时80ms，就要警惕了——很可能是缓存失效或者数据膨胀导致的。所以我在公司内部落地了一个简单的上报逻辑：拦截器里把超过阈值的SQL单独输出成一行WARN日志，包含方法名、耗时、SQL摘要，然后通过日志采集系统上报。DBA每天根据上报结果做一次Review，重点关注那些"平时快、偶尔慢"的SQL。

慢SQL定位这一步，我用过一个笨但有效的方法：把拦截器打印的SQL复制到数据库客户端里执行多次，取平均耗时，和拦截器打印的耗时做对比。差值大说明问题在应用层（网络、连接池、结果映射），差值小说明问题在数据库侧（索引失效、锁等待、大表扫描）。这个方法不需要引入额外工具，任何人照着做就能定位到问题的大致方向。

4.3 从一条日志发现索引失效的完整排查链路

说个实际案例，更能体现这个拦截器的价值。

有一次线上接口响应变慢，平均响应时间从200ms涨到了800ms。我打开日志系统，搜索那段异常期间的SQL执行日志，发现一条SQL引起了注意：

执行方法: com.example.shop.mapper.OrderMapper#getOrderDetail() 执行耗时: 512 ms 执行SQL: SELECT * FROM order_info WHERE order_status = 'PAID' AND user_id = 10234

这条SQL单独执行应该不会这么慢，因为SQL里涉及user_id = 10234精确匹配，这个字段有索引。但耗时512ms明显异常。我把这条SQL复制到测试库执行，EXPLAIN一看，发现order_status = 'PAID'这一列上有一个隐式转换问题——order_status字段类型是varchar，但代码里传入了整型参数，导致该条件无法命中索引，走了全表扫描。

这个问题的根因是SQL参数类型与数据库字段类型不匹配，日志里那行"执行SQL"如果只打印占位符SQL，你根本看不出参数是什么类型，但我的拦截器把参数值替换进了SQL，SQL里显示的是'PAID'这样一个字符串，看起来完全正常。反而是在参数值替换的过程中，formatParameter对值的处理暴露了类型问题——value是Integer类型的数值。顺着这个线索一查，果然发现了传参类型错误。

这类问题排查，没有完整SQL日志的情况下，往往要折腾大半天。有了方法名、完整参数、耗时三件套，定位链路非常清晰。

5. 进阶玩法：结合AOP统计Service层方法与SQL执行时间的对应关系

拦截器拿到的是Mapper层（DAO层）的SQL执行信息，但在实际业务场景里，一个Service方法通常会调用多个Mapper方法。比如一个"创建订单"接口，底层会调用订单插入、库存扣减、余额更新等多个SQL。单看每个SQL的耗时都不高，但整个事务提交之后每次接口调用总要花个几秒，这种情况就需要结合Service层方法来看。

5.1 用AOP切面记录Service方法耗时

解决这个问题也不难，思路是通过AOP对Service层方法做切面统计，然后和Mapper层的SQL日志做同一次请求维度上的关联。网上关于"使用前置通知统计方法执行时间"、“使用环绕通知统计所有带参方法的执行时间”这类需求的讨论很多，本质上就是Spring AOP的标准应用。

我用环绕通知写了一个简单的Service耗时切面，利用ThreadLocal把当前请求的耗时上下文串联起来：

@Aspect @Component public class ServiceCostAspect { private static final Logger log = LoggerFactory.getLogger(ServiceCostAspect.class); // 用ThreadLocal记录当前线程的调用链耗时上下文 private static final ThreadLocal<StopWatchHolder> HOLDER = new ThreadLocal<>(); @Around("execution(* com.example.service..*.*(..))") public Object logServiceCost(ProceedingJoinPoint joinPoint) throws Throwable { String className = joinPoint.getSignature().getDeclaringTypeName(); String methodName = joinPoint.getSignature().getName(); StopWatchHolder holder = HOLDER.get(); if (holder == null) { holder = new StopWatchHolder(); HOLDER.set(holder); } int depth = holder.enter(); try { long start = System.currentTimeMillis(); Object result = joinPoint.proceed(); long elapsed = System.currentTimeMillis() - start; holder.exit(depth); // 只在最外层Service方法结束时打印汇总 if (depth == 1) { log.info("Service方法 [{}.{}] 总耗时: {}ms，内部SQL执行总耗时: {}ms，SQL调用次数: {}", className, methodName, elapsed, holder.getTotalSqlTime(), holder.getSqlCount()); } return result; } finally { if (depth == 1) { HOLDER.remove(); } } } static class StopWatchHolder { private int depth; private long totalSqlTime; private int sqlCount; int enter() { return ++depth; } void exit(int currentDepth) { // no-op, depth restore handled by parent } void addSqlTime(long time) { this.totalSqlTime += time; this.sqlCount++; } long getTotalSqlTime() { return totalSqlTime; } int getSqlCount() { return sqlCount; } } }

这里核心思路是：用ThreadLocal维护一个调用栈深度，当进入最外层Service方法时（depth=1）才做汇总打印。这个方案能拿到整个Service方法的总耗时，但想让SQL执行时间和Service方法关联上，还需要在SqlLogInterceptor里同步把每次SQL的执行时间累加到HOLDER中。

实际做法是在SqlLogInterceptor的printSqlLog方法中，把executeTime登记到HOLDER的addSqlTime方法里：

ServiceCostAspect.StopWatchHolder holder = HOLDER.get(); if (holder != null) { holder.addSqlTime(executeTime); }

5.2 让每个SQL日志带上次请求标识

如果项目并发量大，还建议给每次请求分配一个唯一的traceId。Spring Cloud Sleuth或者阿里的TTL（TransmittableThreadLocal）都能做到，但最轻量的是在拦截器里直接用UUID生成一个简短请求ID。在Controller入口生成traceId，放进MDC（Mapped Diagnostic Context），然后在SQL日志里打印这个值。这样线上排查时，通过一个traceId就能把一次请求的所有SQL日志串起来。

具体实现不复杂：

// Controller 入口处 MDC.put("traceId", UUID.randomUUID().toString().substring(0, 8)); // SqlLogInterceptor 打印日志 log.info("[traceId={}] {}", MDC.get("traceId"), sqlLogContent);

然后在日志配置里把%X{traceId}加到pattern中，这样每行日志都会自动带上traceId。当整个接口调用链路里出现一条慢SQL，搜索这个traceId就能把Controller、Service、Mapper三层日志全部捞出来。

5.3 数据源连接池监控：从SQL日志看不出来的瓶颈

还有一个很容易被忽略的点：SQL日志只能看到SQL本身的执行耗时，但连接池获取连接（getConnection）的等待时间是完全透明的。在高并发场景下，应用层拿到数据库连接的等待时间往往比SQL执行时间还长。假设连接池最大连接数是20，当20个连接全被占用时，第21个请求会在dataSource.getConnection()这里阻塞，这个时间不算在SQL执行耗时里。

排查这类问题的方法是检查连接池的监控指标。HikariCP自带setPoolName和metrics跟踪，Druid有DruidMonitorFactory做Web监控。更简单的方法是在Service层切面里记录getConnection之前的耗时——也就是Service方法总耗时减去SQL执行总耗时，这个差值如果长期偏大，基本可以推断是连接等待或者业务逻辑里做了非数据库操作（调用外部RPC、加锁等待等）。

我遇到过很多"SQL都快，接口就是慢"的案例，最后都查到了连接池等待和业务线程池排队上。所以部门内部的SQL日志系统，我坚持要求把"Service方法总耗时"和"SQL执行总耗时"一起打印，两个数字一对比，应用层瓶颈和数据库瓶颈一眼就能分开。

6. 避坑手册：自定义SQL日志拦截器的常见问题和最佳实践

写完拦截器只是第一步，真正把这个方案用好，还得跨过几个坑。下面这些经验是我在多个项目里反复踩过之后总结的。

6.1 慢SQL输出过多导致日志爆炸

拦截器一旦上线，最直观的变化就是日志量暴增。查一条列表数据可能只输出一条SQL，但一个批处理任务可能执行上万条SQL，那日志一天的生成量简直就是灾难。

处理方案有三个：

• 分级打印：耗时低于50ms的SQL走DEBUG级别，高于50ms的走INFO级别，高于200ms的走WARN级别。这样平时INFO日志里只保留慢SQL，全量SQL可以在排查问题时临时打开DEBUG。
• 采样打印：对批量操作类的SQL（比如insertBatch），只打印第一批数据和耗时汇总，不逐条打印。可以通过参数类型的判断来实现：如果方法名包含Batch或者参数是Collection类型，就只打印第一条。
• 按环境控制：开发环境全量打印，测试环境打印慢SQL，生产环境只打印异常和超阈值SQL。把打印逻辑做成可配置项，不要硬编码。

6.2 事务内多条SQL耗时分析的方法误区

有同学会想，既然拦截器能拿到单条SQL耗时，那么在同一个事务里，如果把所有SQL的耗时加起来，是不是就等于事务的总耗时？答案是：不完全对等。

事务的总耗时 = 获取连接耗时 + SQL执行总耗时 + 事务提交耗时。其中事务提交耗时尤其容易被忽略。MySQL中，事务提交时要刷redo log、binlog，如果开启了半同步复制还要等备库ACK。这些耗时都不在SQL执行时间里。

另外，如果事务里有查询操作，第一次查询后MySQL会给记录加共享锁，更新操作会加排他锁。这些锁的等待时间会计入后续SQL的执行耗时，所以同一事务内的几条SQL，每条执行耗时可能都偏大。

建议做法：在Service层AOP切面里记录"方法总耗时"与"SQL执行总耗时"的差值，如果差值长期大于20ms，优先排查事务提交开销和锁等待。

还有一个容易误导人的地方：MyBatis的批量操作里面，如果使用ExecutorType.BATCH，多条SQL其实是预编译后批量发送到数据库执行的。拦截器在invocation.proceed()里只能感知到一次Executor调用，但这一次调用内部可能已经执行了100条SQL。打印出来的耗时是100条SQL的总耗时，SQL语句本身只贡献了第一条。这个情况在日志里要特别标注，否则排查问题时会误以为"这条SQL很慢"。

6.3 为什么我的拦截器不生效

拦截器不生效的排查顺序大概是这样的：

1. 确认拦截器是否被注册：Spring Boot项目检查是否有@Component或@Bean注册。多数据源项目尤其要注意，拦截器是绑定在SqlSessionFactory上的，每个数据源都要单独注册。

2. 确认方法签名是否正确：如果你拦截的是Executor类型，但方法签名里的参数类型或者顺序写错了，MyBatis会觉得这个拦截器不匹配，静默跳过。把@Intercepts和@Signature的参数逐个对着MyBatis源码核对一遍。

3. 确认是否被其他拦截器拦截了执行链路：MyBatis的多个拦截器是通过责任链模式串联的。如果先注册的拦截器在plugin()方法里返回了target而不是Plugin.wrap(target, this)，后面的拦截器可能永远无法执行。

4. 确认是否用的是MyBatis-Plus：MyBatis-Plus的MybatisPlusInterceptor有自己的一套拦截器接线方式，如果你用MP的拦截器同时再注册自定义拦截器，顺序和优先级需要额外配置。常见的问题是MP的拦截器把Executor包装了一层，导致你的拦截器拿到的参数类型变成IPage，而不是原始的RowBounds。

6.4 打印SQL中的参数值要不要脱敏

这个一定要重视。我在上面的formatParameter方法里，把所有参数值都直接拼进了SQL日志。这在开发环境没问题，但一旦生产环境输出日志，包含手机号、身份证号、密码哈希值的SQL日志如果泄露，就是严重的安全事故。

建议在拦截器里加一个脱敏策略：

private String maskSensitiveData(String propertyName, Object value) { if (propertyName == null) { return String.valueOf(value); } // 匹配常见的敏感字段名 if (propertyName.contains("password") || propertyName.contains("phone") || propertyName.contains("idCard") || propertyName.contains("email")) { return "***"; } return String.valueOf(value); }

同时，在getRealSql方法里调用这个脱敏逻辑，替换参数值之前先判断字段名是否命中敏感字段。你可能会问，参数对象是个Map或者POJO，propertyName怎么拿到？通过ParameterMapping.getPropertyName()就能拿到。对于Map类型的参数，propertyName就是Map的Key，大多数Mapper方法都会给参数加@Param注解，所以能拿到语义明确的字段名。

6.5 与慢SQL优化本身的结合：看懂拦截器日志里的索引线索

最后聊一个进阶场景。当你在控制台看到一条执行耗时异常偏高的SQL时，下一步通常就是SQL调优。这里分享一个我自己的习惯：

拿到拦截器打印的完整SQL后，我不会直接复制到客户端执行，而是先看SQL里是否存在以下特征：

• SELECT *：只要打印日志里出现SELECT *，大概率存在不必要的字段传输开销，尤其是当表有几十个字段时。
• 多个表 JOIN：JOIN次数超过2次，就需要检查是否真的需要多表关联，还是可以拆分成多次单表查询。
• 子查询嵌套：SQL中出现IN (SELECT ...)，注意MySQL对IN子查询的优化策略在不同版本差异很大，5.7之前经常优化失败。
• 对索引列使用函数：比如WHERE DATE(create_time) = '2024-11-16'，这种写法会导致索引失效。

拦截器日志让这些特征暴露无遗。对比我之前用P6Spy的时候，虽然也能拿到完整SQL，但要结合方法名才能知道这个SQL属于哪个业务模块，而自研拦截器的方法名和SQL在同一行输出，优化起来的动手路径短一大截。

另外，如果你的项目用了MyBatis的<script>动态SQL标签，打印出来的SQL往往经过了MyBatis的拼接处理，SQL里的换行和多余空格已经被规整过，直接EXPLAIN基本没问题。

7. 从打印SQL到SQL审计：这个方案还能怎么扩展

如果你已经成功把上面的拦截器跑起来了，还可以考虑往SQL审计的方向扩展一下。很多团队对数据库操作有合规要求，比如需要记录"谁在什么时间执行了什么SQL"，这个需求用拦截器天然就能满足。

要做到完整的审计功能，在printSqlLog的基础上再增加几个信息维度即可：

• 当前登录用户ID：从Spring Security的SecurityContextHolder或者自定义的UserContext中取。
• 来源IP：从当前请求的RequestContextHolder中取。
• 操作类型：MappedStatement.getSqlCommandType()可以拿到INSERT、UPDATE、DELETE、SELECT的枚举值。
• 涉及的数据库表名：从BoundSql.getSql()中正则匹配出表名（注意动态SQL拼接后可能有多条语句，这个方法好在MyBatis的BoundSql里只有一个主SQL）。

把这些信息组装成一条审计日志，输出到独立的审计日志文件（logback里单独配置一个AuditLogger），就能满足大部分内部审计需求了。如果你接入过审计日志平台（比如日志易、ELK），把审计日志的格式设计成JSON，后续做检索分析会方便很多。

我在实践中的体会是：MyBatis SQL日志打印这件事，表面上是一个"配置一下就能行"的小需求，但深入下去会发现牵涉到日志框架选型、MyBatis插件机制、参数绑定原理、慢SQL排查方法论、安全合规等多方面问题。自己动手写一遍拦截器，比直接用P6Spy或者MyBatis-Plus自带的打印功能收获大得多——因为只有真正理解了Executor拦截链条，你才能在遇到"拦截器不生效""耗时数据不准""参数值泄露"这些问题时不慌不乱，快速定位根因。

最后再分享一个小技巧：在printSqlLog里，除了打印SQL，顺便把mappedStatement.getConfiguration().getVariables()里的自定义变量也打出来。MyBatis的configuration.getVariables()可以用来传递一些全局配置（比如环境标识），把这些信息随SQL一起输出，在上线多个环境时能一眼看出当前日志是哪个环境产生的，避免排查问题拿错了环境。这个细节让我在多人协作的项目里少踩了不少坑。