先吐槽一句后端排错的时候我最离不开的就是SQL日志。但只要公司的项目一接入MyBatis日志这块儿就总有那么点别扭——格式乱、参数看不全、慢SQL全靠肉眼盯。我试了一圈现成的日志组件最后真正解决的问题反而是自己写了一个MyBatis拦截器。整个过程不算长但里面值得展开的细节不少这篇就把我的选型理由、实现思路和踩坑过程一次性说清楚。1. 试了一圈现成方案最终还是要自己动手1.1 MyBatis自带的日志输出为什么不够用MyBatis本身是有日志能力的默认通过LogFactory适配各种日志框架。你只要把org.apache.ibatis.logging.stdout.StdOutImpl配置为日志实现控制台就会看到类似这样的输出 Preparing: SELECT id, name, age FROM user WHERE id ? AND status ? Parameters: 1001(Integer), 1(Integer) Columns: id, name, age Row: 1001, zhangsan, 25 Total: 1这个自带输出信息其实挺全预编译SQL、参数类型、返回列、返回行数都有。但对于“我想看清楚SQL长什么样”这个核心诉求它有两个明显问题。第一它打印的是占位符SQL和参数列表阅读起来要求“脑内拼接”。排查线上问题的时候一条复杂SQL十几个参数我得拿着?和参数列表一个一个对齐效率低还容易对错。第二它没办法按业务场景分级。线上环境开debug级别打SQL日志量巨大磁盘和排查效率都吃不消不开吧又看不到需要的信息。所以绝大多数项目最终都会想搞一个“能输出完整SQL、能自己控制开关、能统计慢SQL”的日志方案。1.2 Druid、p6spy、MyBatis-Plus的日志方案各有各的短板在彻底写自定义拦截器之前我先后用过几种方案这里直接列个对比表格方便你判断是不是也踩过同样的坑。方案优点短板MyBatis自带debug日志零成本配置即用占位符与参数分离线上日志量大格式固定Druid连接池的SQL日志能打印慢SQL可扩展性强需要依赖连接池格式个性化能力一般占位符还原同样要自己处理p6spySQL完整打印格式化效果好要换驱动生产环境多一层代理对性能敏感的项目要慎用MyBatis-Plus的日志输出接入极简单能看SQL和参数有框架绑定配置灵活性低做慢SQL统计、热点监控基本不可能p6spy其实是很成熟的方案打印出来的SQL可以直接复制到数据库工具里执行。但它在真实项目中有一个我比较介意的问题它会让应用层的JDBC调用多一层拦截某些特殊类型或游标场景下排查起来更容易绕圈子。另外对于已经上了MyBatis的项目p6spy打印的SQL不是直接对应MyBatis的Mapper方法你还是很难把“这条SQL慢”和“这个Mapper方法调用慢”对起来。至于Druid的日志如果你用了Druid连接池它自带的Filter可以做不少事情。但它的参数还原逻辑本质上也是拼字符串而且和连接池强绑定。万一将来换连接池这套日志逻辑就废了。所以再三考虑之后我决定不在“外部包装层”上折腾直接在MyBatis内部做文章。这就是自定义拦截器的出发点。2. 想拦截SQL先搞清楚MyBatis四大对象和代理链2.1 四大对象里为什么我选Executor下手MyBatis的核心执行链路由四大对象组成Executor最外层执行器负责调度SQL执行、处理一级/二级缓存、事务边界。StatementHandler负责创建Statement、预编译SQL、绑定参数。ParameterHandler专门负责给PreparedStatement设置参数。ResultSetHandler处理查询结果集到Java对象的映射。很多人一听“SQL日志拦截器”第一反应是拦截StatementHandler觉得这才是离SQL最近的地方。确实拦截StatementHandler.prepare可以拿到完整的BoundSql也可以拿到连接对象。但从它身上拿不到最终返回结果的数量也难在它这一层统一统计一次查询的耗时。我最终选择拦截Executor理由有几点Executor.query和Executor.update是所有Mapper方法执行的必经之路在这里能同时覆盖增删改查。通过MappedStatement.getBoundSql(parameterObject)可以直接拿到包含动态SQL拼接结果的BoundSql。调用invocation.proceed()返回值后查询场景能拿到List更新场景能拿到int天然适合做耗时统计和结果行数统计。这一层能感知二级缓存是否命中符合“用户视角的SQL请求日志”定位。2.2 Interceptor接口与Plugin.wrap的代理机制MyBatis自定义拦截器实现起来其实不复杂核心就两件事用Intercepts和Signature声明你要拦截谁、拦它的哪个方法然后实现Interceptor接口里的intercept方法。看一个最标准的拦截器骨架Intercepts({ Signature(type Executor.class, method query, args {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}), Signature(type Executor.class, method update, args {MappedStatement.class, Object.class}) }) public class SqlLogInterceptor implements Interceptor { Override public Object intercept(Invocation invocation) throws Throwable { return invocation.proceed(); } }Signature里的三要素一个都不能错type是目标接口类型method是方法名args是方法形参类型列表。注意这个形参类型必须和接口定义完全一致连顺序都不能反否则拦截器注册成功但方法不会触发。它的代理机制比较简单Interceptor接口默认的plugin方法会调用Plugin.wrap(target, this)生成一个JDK动态代理。当代理对象被调用时如果当前方法命中了注解里声明的签名就进入intercept方法没命中就直接反射调用原方法。多个拦截器作用于同一个目标对象时会产生嵌套代理。谁先被Configuration.addInterceptor添加谁就包在更外层。这一点很关键后面讲和分页插件共存时会再度提到。还有一个大家常犯的错误intercept方法里不写invocation.proceed()。一旦漏掉SQL就不会真正执行接口直接返回null。这相当于把整个Mapper调用给“吞”了。所以只要写自定义拦截器第一行就该把invocation.proceed()的调用逻辑想清楚所有日志行为都要围绕它展开。3. 一个可直接抄作业的SQL日志拦截器3.1 拦截Executor的query和update并让日志只输出一次核心实现我放在一个类SqlLogInterceptor里。第一次写的时候我下意识把所有Executor.query重载都列进了Signature结果日志一条SQL打印了两遍。原因很简单CachingExecutor的四参数query方法在内部会调用六参数的query方法两个方法都被拦截自然就会逐个触发。所以实际生产环境我只拦截四参数的query和两参数的update。四参数query已经是所有SQL查询的统一入口能覆盖二级缓存命中场景也不会重复打印。完整代码如下Intercepts({ Signature(type Executor.class, method query, args {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}), Signature(type Executor.class, method update, args {MappedStatement.class, Object.class}) }) public class SqlLogInterceptor implements Interceptor { private static final Logger SQL_LOGGER LoggerFactory.getLogger(SQL_LOG); private long slowThresholdMillis 3000L; private boolean printResultSize true; Override public Object intercept(Invocation invocation) throws Throwable { Object target invocation.getTarget(); if (!(target instanceof Executor)) { return invocation.proceed(); } MappedStatement ms (MappedStatement) invocation.getArgs()[0]; Object parameter invocation.getArgs()[1]; BoundSql boundSql ms.getBoundSql(parameter); String sql completeSql(boundSql, parameter); long start System.nanoTime(); Object result invocation.proceed(); long elapsedMillis TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start); int rowCount parseResultCount(result); String method invocation.getMethod().getName(); if (elapsedMillis slowThresholdMillis) { SQL_LOGGER.warn(slow [{}] with {}ms, rows{}, sql: {}, method, elapsedMillis, rowCount, sql); } else { SQL_LOGGER.debug({} with {}ms, rows{}, sql: {}, method, elapsedMillis, rowCount, sql); } return result; } private int parseResultCount(Object result) { if (result instanceof List) { return ((List?) result).size(); } if (result instanceof Integer) { return (Integer) result; } return 0; } Override public void setProperties(Properties properties) { if (properties null) { return; } this.slowThresholdMillis Long.parseLong(properties.getProperty(slowThresholdMillis, 3000)); this.printResultSize Boolean.parseBoolean(properties.getProperty(printResultSize, true)); } }注意有几个细节parseResultCount里把List和Integer分开处理。查询返回的是List增删改返回的是受影响行数不要让统一逻辑把两种结果搞混。System.nanoTime()比System.currentTimeMillis()更适合测耗时后者受系统时间跳变影响前者是单调时钟。慢SQL用warn级别输出普通SQL用debug级别输出。这样生产环境日志级别一旦调低普通SQL不会刷屏慢SQL依然能保留下来。3.2 占位符还原从BoundSql和ParameterMapping解析参数这是拦截器里最核心也是最容易写错的部分。BoundSql里有原始SQL和parameterMappingsparameterMappings里每一项都对应SQL中的一个?并且带着参数属性名。我按顺序把参数值和?一一替换就能拼出可直接执行的完整SQL。private String completeSql(BoundSql boundSql, Object parameterObject) { String sql boundSql.getSql().replaceAll(\\s, ).trim(); ListParameterMapping parameterMappings boundSql.getParameterMappings(); if (parameterMappings null || parameterMappings.isEmpty()) { return sql; } StringBuilder builder new StringBuilder(sql); int offset 0; for (ParameterMapping mapping : parameterMappings) { int placeholderIndex builder.indexOf(?, offset); if (placeholderIndex 0) { break; } Object value resolveValue(boundSql, mapping.getProperty(), parameterObject); String valueText formatValue(value); builder.replace(placeholderIndex, placeholderIndex 1, valueText); offset placeholderIndex valueText.length(); } return builder.toString(); } private Object resolveValue(BoundSql boundSql, String property, Object parameterObject) { Object value null; if (parameterObject instanceof Map) { value ((Map?, ?) parameterObject).get(property); } else if (parameterObject ! null) { MetaObject metaObject SystemMetaObject.forObject(parameterObject); if (metaObject.hasGetter(property)) { value metaObject.getValue(property); } } if (value null) { value boundSql.getAdditionalParameter(property); } return value; } private String formatValue(Object value) { if (value null) { return NULL; } if (value instanceof CharSequence) { String text value.toString().replace(, ); return text ; } if (value instanceof Date) { Date date (Date) value; SimpleDateFormat sdf new SimpleDateFormat(yyyy-MM-dd HH:mm:ss); return sdf.format(date) ; } if (value instanceof Boolean || value instanceof Number) { return value.toString(); } return value.toString() ; }MetaObject是MyBatis自带的反射工具类能访问对象属性也能处理user.name这种嵌套属性路径。这里要保底走一下boundSql.getAdditionalParameter(property)因为动态SQL的foreach会生成额外的参数比如__frch_item_0这些参数不在原始传入的parameterObject里而是放在BoundSql的附加参数中。indexOf方法比replaceFirst稳。replaceFirst用的是正则如果我们打印的SQL里恰好有正则特殊字符会造成误替换。3.3 Spring Boot与XML两种注册方式拦截器写完之后注册方式取决于你的项目配置。如果是纯MyBatis配置在mybatis-config.xml里加一段plugins plugin interceptorcom.example.interceptor.SqlLogInterceptor property nameslowThresholdMillis value3000/ property nameprintResultSize valuetrue/ /plugin /plugins如果是Spring Boot项目我建议通过ConfigurationCustomizer注册这种方式不依赖MyBatis-Plus的自动收集逻辑兼容性最好Configuration public class MyBatisConfig { Bean public SqlLogInterceptor sqlLogInterceptor() { SqlLogInterceptor interceptor new SqlLogInterceptor(); Properties properties new Properties(); properties.setProperty(slowThresholdMillis, 3000); properties.setProperty(printResultSize, true); interceptor.setProperties(properties); return interceptor; } Bean public ConfigurationCustomizer sqlLogConfigurationCustomizer(SqlLogInterceptor sqlLogInterceptor) { return configuration - configuration.addInterceptor(sqlLogInterceptor); } }如果项目里已经用mybatis-spring-boot-starter直接定义Interceptor类型的Bean能不能被自动注册这个行为在不同版本里不完全一致。为了不赌运气我用的是ConfigurationCustomizer注册认证之后非常稳。4. 参数还原的细节坑看似简单踩了才知道4.1 Map、嵌套属性与foreach产生的特殊参数第一版拦截器上线后第一个翻车场景是foreach。我写了一条WHERE id IN (...)的查询SQL日志打出来之后占位符后面的参数全是__frch_item_0、__frch_item_1这种格式一个有效的值都看不到。原因就是前面提到的foreach的每一项并不是直接存放在用户传入的parameterObject里而是MyBatis在执行动态SQL时把拆分后的参数塞进了BoundSql.additionalParameters。所以参数解析逻辑必须加一步兜底Map/Bean/嵌套属性里取不到就从additionalParameter里去取。另一个容易出问题的是Map参数加嵌套路径。MyBatis允许在Mapper接口里这么写select idfindUser resultTypeUser SELECT * FROM user WHERE department.name #{dept.name} AND status #{status} /select参数对象是个MapMap里的key是deptvalue是另一个Map或对象。这时resolveValue单纯执行map.get(dept.name)是拿不到值的需要自己写一个逐级查找的逻辑。我给的示例里之所以用MetaObject处理对象就是它能直接解析这种带点路径的属性名但Map的get不支持点路径所以我建议在实际代码里多加一个方法对Map类型先判断是否存在点号存在就逐层get下去。4.2 日期、字符串、NULL的格式化规则formatValue看着简单但格式规则直接决定你拼接出来的SQL能不能直接在数据库客户端执行。字符串不加单引号拼出来的SQL一定会让数据库报错。字符串本身含单引号比如OBrien直接拼接会导致SQL语句被破坏需要用两个单引号转义。日期不格式化往往打出的是Timestamp的一长串毫秒名看起来不直观我用yyyy-MM-dd HH:mm:ss格式化已经能满足绝大多数调试场景。NULL必须显式大写否则拼接出来是空字符串完全改变了SQL的语义。这里多说一句日志拦截器拼接的SQL只是用于查看它并不会真正替代JDBC预编译机制。安全上MyBatis的#{}参数本来就是通过PreparedStatement绑定传进去的日志显示完整SQL并不是SQL注入的入口这一点不要混淆。我的做法是只有在打印SQL的层面上才是“完整拼好”数据库执行时仍然走参数化绑定。如果有特殊类型比如枚举、数组、自定义对象我的formatValue默认是走toString并加引号。数组和集合类型会打出[Ljava.lang.String;xxxx这种地址确实很难看。一般我会在formatValue里加一个判断如果值是数组或集合就转成[1, 2, 3]这种可读格式。不过这属于锦上添花线上项目里直接用集合作为单参数值的情况其实不算多。5. 从打印到监控慢SQL日志和热点统计5.1 慢SQL阈值、调用来源与traceId有了完整的SQL拼接能力之后加慢SQL监控就顺理成章了。我第二部分在intercept里已经加上了耗时判断String traceId MDC.get(traceId); String source buildSource(); // 从StackTrace中取非MyBatis的调用位置 if (elapsedMillis slowThresholdMillis) { SQL_LOGGER.warn(traceId{}, source{}, slow sql [{}ms], rows{}, sql: {}, traceId, source, elapsedMillis, rowCount, sql); } else { SQL_LOGGER.debug(traceId{}, source{}, sql [{}ms], rows{}, sql: {}, traceId, source, elapsedMillis, rowCount, sql); }traceId从MDC里拿如果项目已经接了SkyWalking或自定义的全链路追踪这一步很简单。没有全链路追踪的话也可以直接用日志框架的MDC塞一个基于UUID的链路ID。调用来源这一项我实现了一个比较轻量的方式拿到当前线程的StackTrace数组从外往里找第一个不是MyBatis内部框架包名的类和方法。这样慢SQL日志能直接定位到“是哪个Service类里的哪一行代码触发慢查询”而不是每次都从Mapper方法反查业务入口。5.2 简单的热点SQL统计慢SQL日志只能解决“事后看单条”的问题但生产环境经常有“单条不慢整体很频繁”的SQL它才是拖垮数据库的隐形杀手。所以我给拦截器加了一个内存统计功能private ConcurrentHashMapString, AtomicLong countMap new ConcurrentHashMap(); private ConcurrentHashMapString, AtomicLong totalTimeMap new ConcurrentHashMap();把SQL按Mapper方法名为key做统计每次执行就累加次数和总耗时。每隔一定时间或日志量达到阈值输出一份热点SQL排行热点SQL TOP5: 1. findUserByCondition - 调用次数: 12580, 平均耗时: 220ms, 最大耗时: 1600ms 2. updateUserStatus - 调用次数: 3210, 平均耗时: 13ms, 最大耗时: 200ms这个功能不用做得很复杂ConcurrentHashMap加AtomicLong就够用了。毕竟日志拦截器的核心本职是打印统计只是辅助决策。生产环境我会把这份热点表输出到一个单独的logger方便定时任务来分析。不过要提醒一点内存统计在并发量很高的服务上会有轻微开销但只是用原子计数不会造成性能问题。如果你的系统QPS在几万以上又不想要任何额外开销建议直接关掉统计保留基础日志打印就够。6. 和MyBatis-Plus、分页插件一起用时的顺序问题6.1 多个拦截器顺序和日志是否打印出真实SQL的关系如果你的项目用了MyBatis-Plus分页插件那Executor上至少有两个拦截器一个是我写的SQL日志拦截器一个是分页插件。两者都拦截同一个Executor.query方法执行顺序就取决于注册顺序。关键坑在于日志拦截器如果包在分页插件外层invocation.proceed()还没调当时分页插件还没对SQL做物理分页改写所以日志里打出来的是不带LIMIT的原始SQL而真正执行的是带LIMIT的SQL。这会让排查分页场景的慢SQL变得困惑。如果要打印出最终执行的、包含分页条件的SQL需要让日志拦截器“包在内层”也就是后注册的那个反而更早执行。InterceptorChain的pluginAll方法会依次调用每个拦截器的plugin方法最后一个添加的拦截器生成的代理会包在所有之前代理的最外层。这句话反直觉我在实际项目里验证过确实如此。所以实际操作建议如果你希望日志展示原始Mapper SQL那把日志拦截器放分页插件前面。如果你希望日志展示最终执行SQL包括分页条件把日志拦截器放分页插件后面。这个“后面”指的是在Configuration里后执行addInterceptor对应到XML配置里就是plugins标签里写在分页插件的下方。6.2 日志打印遗漏和重复的两个排查思路多拦截器共存时最常碰到的两个现象分别是对应两个完全相反的原因。现象一日志变少了有些SQL打不出来。十有八九是拦截器的Signature漏了某个方法或者某个请求路径根本没有按预期走那个重载方法。比如我之前说过如果你只拦截六参数的query二级缓存命中时六参数方法根本不会被触发日志自然就少。要避免这种情况最稳妥的是拦住四参数入口。现象二日志重复打印一条SQL打两次。这往往是因为同时拦截了query的四参和六参两个重载导致CachingExecutor里四参方法调用六参方法时又触发了一次。解决办法很简单只留一个入口或者用ThreadLocal做一个标记位进入后置为true外层的四参方法打印后清除标记六参方法看到标记就不再打印。这两个问题几乎每个写MyBatis拦截器的人都会遇到排查思路也简单先在intercept方法入口打一行临时日志确认当前拦截的是哪个方法、参数是什么再根据调用栈判断是哪一层触发的。能快速排水落石出。另外还有一个容易被忽略的点如果你现场加了多个拦截器又发现别人写的拦截器在intercept里不调用proceed()或者自行抛了异常后面的拦截器和原始执行逻辑就全断了。这种问题排查起来非常消耗精力所以多拦截器项目里最好约定的第一条规矩就是自定义拦截器永远完整执行invocation.proceed()除非你就是想阻断这条链路。结尾没有额外总结就用一段自己的体会收住吧这个拦截器从第一版只能打SQL到后面可以做慢SQL预警、热点统计前后迭代了不少次。但核心的价值一直没变——它让我在排查问题时能像操作数据库客户端一样直接看到参清单、耗时、行数和调用来源。如果你也一直被MyBatis日志的格式和粒度困扰按这套思路自己搭一个吧实现成本远比你想象的低收益却非常直接。