★ FEATURED ARTICLE 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接口的日志级别调到DEBUGlogging: level: com.example.mapper: debug这样MyBatis-Plus会把SQL、参数、执行结果都打出来但格式依然受限于MyBatis默认的日志输出格式。更重要的是MP的SQL分析插件更侧重于慢SQL告警和分页优化比如你可以设置maxLimit防止全表查询可以通过PerformanceInterceptor的maxTime属性来输出超过指定阈值的SQL。但执行方法名的输出MP也没有做。2.2 用P6Spy打印完整SQLP6Spy的思路和MyBatis完全不同它是在JDBC层面做代理。P6Spy会拦截所有经过JDBC的SQL请求重新拼接参数后输出完整可执行的SQL语句MyBatis默认打印的是带?占位符的预编译SQL很多同学嫌它不能直接复制到数据库执行P6Spy恰好解决了这个问题。配置P6Spy需要这几步引入依赖dependency groupIdp6spy/groupId artifactIdp6spy/artifactId version3.9.1/version /dependency修改数据源URL加上p6spy前缀spring.datasource.url: jdbc:p6spy:mysql://localhost:3306/demo_db spring.datasource.driver-class-name: com.p6spy.engine.spy.P6SpyDriver配置spy.properties文件appendercom.p6spy.engine.spy.appender.Slf4JLogger logMessageFormatcom.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 ThreadLocalSimpleDateFormat 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(); ListParameterMapping 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的字段是jdbcUrlDruid的是url我上面的反射代码默认找url字段遇到HikariCP就会拿不到。如果你想兼容多种连接池建议多看一层。不过话说回来打印数据库连接信息只是辅助排查用的拿不到也不影响主流程。这里我再补充一个事务的场景。当你在一个事务里执行了多条SQL这些SQL是在同一个数据库连接上执行的。如果你在事务方法里启动了MyBatis的批量操作或者多次查询拦截器会分别打印每一条SQL的日志但它们共享同一条数据库连接。这个信息对于排查连接池泄漏、死锁问题非常有用所以我在日志里加了数据库连接地址一栏。3.3 注册拦截器并验证效果在Spring Boot项目中最简单的做法就是把这个类加上Component注解MyBatis在初始化时会自动扫描到并且注册。如果你的项目是多数据源建议使用Bean方式手动注册指定给某个特定的SqlSessionFactoryConfiguration 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?useSSLfalsecharacterEncodingutf8 执行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 ListString IGNORED_METHODS Arrays.asList(selectCount); // 白名单只打印关键业务方法 private static final ListString WATCH_METHODS Arrays.asList(updateUser, insertBatch);然后在printSqlLog里做匹配过滤。这个功能在实际项目中很有用——开发阶段全量打印上线后只保留慢查询或指定方法的日志避免日志量过大。4. 从打印SQL到看清性能慢SQL定位与执行耗时剖析工具做出来了更重要的是怎么用它解决实际问题。我在公司项目里落地这个拦截器之后最直接的收益就是慢SQL定位从靠猜变成了看图说话。4.1 执行耗时的三个层次要理解执行耗时得先分清SQL耗时的构成。一次完整的数据库操作耗时可以分为三个阶段网络传输耗时客户端到数据库服务器之间的网络往返延迟。每次请求数据都要经过TCP连接、SSL握手如果开启、数据包传输。如果数据库和应用部署在两台机器上这个耗时通常是稳定的一两毫秒但如果跨机房访问可能飙升到几十毫秒。数据库执行耗时数据库引擎真正执行SQL的时间包括解析SQL、生成执行计划、扫描数据、回表查数据等。这个耗时受索引、数据量、锁竞争影响最大。JDBC驱动与MyBatis的解析耗时MyBatis把结果集映射成Java对象的时间以及JDBC驱动的编解码时间。我的Interceptor拿到的耗时是整个invocation.proceed()的耗时它包含了上面全部三部分而不仅仅是数据库执行时间。所以如果你发现某条SQL打印出来耗时为50ms但这条SQL在数据库客户端里执行只要5ms那么剩余45ms很可能花在应用层到数据库的网络传输或者MyBatis的结果映射上。怎么进一步区分是哪一层的耗时我分享一个实操技巧直接看SQL对应方法返回的结果集大小。如果select返回几百条数据耗时偏高大概率是数据库执行慢或者网络传输慢如果返回上万条数据耗时偏高大概率是MyBatis结果映射慢。之前我遇到过一个项目一条SQL查询出来的数据有5万多行每次执行耗时稳定在180ms但这条SQL本身只有40ms。后来排查发现问题出在resultMap里配置了多个嵌套子查询N1查询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你根本看不出参数是什么类型但我的拦截器把参数值替换进了SQLSQL里显示的是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 ThreadLocalStopWatchHolder 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执行总耗时: {}msSQL调用次数: {}, 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方法时depth1才做汇总打印。这个方案能拿到整个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或者阿里的TTLTransmittableThreadLocal都能做到但最轻量的是在拦截器里直接用UUID生成一个简短请求ID。在Controller入口生成traceId放进MDCMapped 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 为什么我的拦截器不生效拦截器不生效的排查顺序大概是这样的确认拦截器是否被注册Spring Boot项目检查是否有Component或Bean注册。多数据源项目尤其要注意拦截器是绑定在SqlSessionFactory上的每个数据源都要单独注册。确认方法签名是否正确如果你拦截的是Executor类型但方法签名里的参数类型或者顺序写错了MyBatis会觉得这个拦截器不匹配静默跳过。把Intercepts和Signature的参数逐个对着MyBatis源码核对一遍。确认是否被其他拦截器拦截了执行链路MyBatis的多个拦截器是通过责任链模式串联的。如果先注册的拦截器在plugin()方法里返回了target而不是Plugin.wrap(target, this)后面的拦截器可能永远无法执行。确认是否用的是MyBatis-PlusMyBatis-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或者POJOpropertyName怎么拿到通过ParameterMapping.getPropertyName()就能拿到。对于Map类型的参数propertyName就是Map的Key大多数Mapper方法都会给参数加Param注解所以能拿到语义明确的字段名。6.5 与慢SQL优化本身的结合看懂拦截器日志里的索引线索最后聊一个进阶场景。当你在控制台看到一条执行耗时异常偏高的SQL时下一步通常就是SQL调优。这里分享一个我自己的习惯拿到拦截器打印的完整SQL后我不会直接复制到客户端执行而是先看SQL里是否存在以下特征SELECT *只要打印日志里出现SELECT *大概率存在不必要的字段传输开销尤其是当表有几十个字段时。多个表 JOINJOIN次数超过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一起输出在上线多个环境时能一眼看出当前日志是哪个环境产生的避免排查问题拿错了环境。这个细节让我在多人协作的项目里少踩了不少坑。
阅读完成 · 觉得有帮助？
