ARTICLE DETAIL

资讯详情

深耕网站建设与运营推广的一线实战洞察。

MyBatis自定义拦截器:输出完整可执行SQL日志的实战指南

MyBatis自定义拦截器:输出完整可执行SQL日志的实战指南 写后端这几年最烦躁的一类日志就是MyBatis默认打出来的那三行。 Preparing: SELECT * FROM user WHERE id ? AND status ? Parameters: 1(Long), 2(Integer) Columns: id, name, age, create_time Row: 1, 张三, 25, 2024-01-01 10:00:00参数和SQL分开两行线上排查慢SQL的时候从日志平台捞到这么一条记录想拿它去数据库里复现一下得自己动手把问号一个个替换成真实参数。运气不好碰上IN (?, ?, ?, ?...)这种十几个占位符的手拼SQL拼到怀疑人生。所以今天这篇文章就是来解决这个问题的写一个自定义MyBatis拦截器让日志直接输出一条能在Navicat里原样运行的完整SQL带上参数、耗时、甚至影响行数一眼看过去就知道这条SQL到底长什么样。这个内容适合所有用Spring Boot MyBatis / MyBatis-Plus 做开发的Java后端不管你是刚接触拦截器的新手还是已经写过插件想优化日志的老手都能在这篇文章里找到可以抄作业的代码和文档里不会写的坑。1. 系统自带的MyBatis日志为什么就是不够用1.1 默认三段式日志到底差在哪先说个结论MyBatis默认日志不是不能看是在“问题排查”这个场景下太低效了。三段式日志把Preparing预处理SQL、Parameters参数、Columns/Row结果集分开打印这对框架本身来说是合理的因为它本质上是把“JDBC执行过程”一段段打给你看。但对排查问题的人来说差在三个点上。第一SQL和参数分离。拿到一条Preparing的日志SQL里的问号对应哪个参数得按顺序去Parameters那行找一旦SQL超过20行眼睛基本就看花了。更别说生产环境日志量大这两行消息在日志系统里可能是完全独立的文档检索时好不容易捞到一条另一条可能压根没采到。第二没有耗时。默认日志不会告诉你这条SQL跑了多少毫秒。慢SQL排查第一步是“找哪些SQL慢”如果你用的是默认日志就得自己看时间戳之间的差值或者额外配慢查询监控非常不方便。第三动态SQL拼接过程不可见。MyBatis的if、foreach这些标签在日志里只能看到最终执行的完整SQL中间哪个条件没拼进去、哪个循环生成了一堆问号你完全看不出来。这时候如果能直接把最终SQL完整打印出来动态SQL的生成结果一眼就能确认。1.2 一条完整可执行SQL能带来什么我自己的体会是当你把“SQL 参数”合并成一行/一段输出以后整个排查效率是质的提升。举个例子。线上收到告警说订单表order_info有一条慢SQL耗时2秒。默认日志模式下你得先找到那段日志然后手动把参数替换进去再用客户端连上数据库执行手动加EXPLAIN看执行计划。这套流程熟练的话至少5分钟。但如果你配了SQL日志拦截器日志里直接是这样的SELECT id, order_no, user_id, amount, status, create_time FROM order_info WHERE status 1 AND create_time BETWEEN 2024-01-01 00:00:00 AND 2024-12-31 23:59:59 ORDER BY id DESC LIMIT 1000; -- Cost: 205ms直接整条复制到Navicat里跑跌倒了先EXPLAIN分析索引有没有走两分钟就搞定。这种体验用过一次就回不去了。另外还有一个很实用的场景把日志发给DBA或者同事排查。对方不需要你额外提供参数列表一条完整SQL丢过去对方直接能复现沟通成本直线下降。2. 自定义拦截器的原理其实就两件事2.1 四大核心对象与插件的“钩子”位置很多人一听“MyBatis拦截器”觉得高大上其实拆开看就两件事找到能下手的地方然后在那个地方做手脚。MyBatis允许我们拦截的对象是框架内部的四个核心组件Executor、StatementHandler、ParameterHandler、ResultSetHandler。这四个对象分别管什么我打个比方。一条SQL从Mapper接口到数据库执行大致走这条路Executor执行器接单StatementHandler语句处理器负责把SQL编译成JDBC的StatementParameterHandler参数处理器负责把?占位符设置成真实参数ResultSetHandler结果集处理器负责把数据库返回的结果集转换成Java对象。拦截器就是在这条链路上挂一个切面。你选择拦哪个对象就决定了你“下手”的时机。拦Executor能拿到MappedStatement包含了SQL声明信息、参数对象、分页参数RowBounds执行完以后还能拿到结果集统计查询行数很方便但它被称为“最外层”很多第三方插件比如PageHelper都是拦这一层容易产生冲突。拦StatementHandler是“SQL编译后、未执行前”的时机能拿到BoundSql里面是完整SQL和参数映射信息也能拿到ParameterHandler拿到真实参数值打印SQL日志是首选。拦ParameterHandler能拿到参数对象但如果要拼完整SQL需要结合BoundSql的映射关系复杂一些。拦ResultSetHandler一般用在结果集二次处理上比如数据脱敏、字段加密。我最终选择的是拦StatementHandler.prepare方法原因下面实战部分细说。2.2 Signature到底该怎么写才不踩坑MyBatis拦截器核心代码里有个注解Intercepts里面写Signature。很多新手在这里就踩坑了最常见的问题是method名字写对了但args参数类型写错导致拦截器死活不生效。以拦截StatementHandler为例标准写法是Intercepts({ Signature( type StatementHandler.class, method prepare, args {Connection.class, Integer.class} ) }) public class SqlLogInterceptor implements Interceptor { // ... }这里有个版本细节早期MyBatis的prepare方法签名是prepare(Connection connection, Integer transactionTimeout)后来有的版本变成了prepare(Connection connection, Integer transactionTimeout)或者少参数的prepare(Connection connection)。如果你碰到“拦截器注册了但就是不执行”的情况优先检查args的类型特别是Integer和int的区别——这里必须写包装类型写基本类型int.class是匹配不上的。更稳妥的做法是打开你项目里依赖的MyBatis版本直接看StatementHandler.class的源码找prepare方法的确切签名然后照着写。2.3 拦截器和Spring Boot是怎么配合的另一个常见误区是拦截器到底要不要交给Spring管理MyBatis的拦截器机制是在SqlSessionFactory更准确说是Configuration构建时通过动态代理包一层加进去的。Spring Boot 项目用mybatis-spring-boot-starter时如果配置类里声明了一个实现了org.apache.ibatis.plugin.Interceptor接口的Bean新版本的starter会自动把这个Bean注册进Configuration。如果你用的mybatis-spring-boot-starter版本比较老或者你用的是MyBatis-Plus全家桶可能出现“注册了但没生效”的情况。这时候用最原始的方法手动注入SqlSessionFactory显式调用factory.getConfiguration().addInterceptor(interceptor)这就一定不会漏。Configuration public class MyBatisConfig { Bean public SqlSessionFactory sqlSessionFactory(DataSource dataSource, SqlLogInterceptor sqlLogInterceptor) throws Exception { SqlSessionFactoryBean factoryBean new SqlSessionFactoryBean(); factoryBean.setDataSource(dataSource); factoryBean.setPlugins(new Interceptor[]{sqlLogInterceptor}); return factoryBean.getObject(); } }这块要说明一下如果你想留出Configuration交给starter自动配置的默认行为最快的方式就是只声明一个SqlLogInterceptor的Bean然后把上面这段代码注释掉重启测试一下能不能生效。我自己实测下来新版starter能识别老版识别不了识别不了就手动加不丢人。3. 手把手实现一个SQL日志拦截器3.1 先选对拦截目标StatementHandler还是Executor我在真正写这个拦截器之前先试过两种方案各有取舍这里直接说结论。方案A拦截Executor.query/update优点是可以拿到MappedStatement执行完成后还能拿到结果集查一下List.size()就是查询行数也可以拿到更新影响行数。缺点很明显和 PageHelper、MyBatis-Plus的分页插件、乐观锁插件可能撞车因为你也是在Executor层做手脚拦截器执行顺序会互相影响出了问题排起来麻烦。方案B拦截StatementHandler.prepareprepare是真正要创建JDBCStatement的时机也就是说SQL马上要发给数据库了。这个位置能拿到BoundSql里面包含了最终SQL和参数映射也能通过ParameterHandler.getParameterObject()拿到真实参数。它不碰Executor所以跟分页插件冲突的几率极小。我做SQL日志最终选的是方案B。因为我的核心需求就是“看SQL长什么样”越靠近真实的JDBC执行层看到的SQL和参数越准确而且不干扰业务逻辑。另外注意到一个细节如果二级缓存命中了Executor.query可能会直接返回缓存结果根本不会走到StatementHandler.prepare所以拦截prepare打出来的日志是真正打到数据库的那批SQL。如果你的监控目标是“数据库负载”这恰好是你要看的。3.2 完整代码与逐步讲解下面这个类就是完整实现可以直接复制到你的项目里用。我尽量把注释写清楚每一步都告诉你想干什么。package com.example.common.interceptor; import org.apache.ibatis.binding.MapperMethod; import org.apache.ibatis.executor.parameter.ParameterHandler; import org.apache.ibatis.executor.statement.StatementHandler; import org.apache.ibatis.mapping.BoundSql; 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.type.JdbcType; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.stereotype.Component; import java.sql.Connection; import java.text.SimpleDateFormat; import java.util.Date; import java.util.List; import java.util.Map; import java.util.Properties; Intercepts({ Signature( type StatementHandler.class, method prepare, args {Connection.class, Integer.class} ) }) Component public class SqlLogInterceptor implements Interceptor { private static final Logger log LoggerFactory.getLogger(SQL_LOG); Override public Object intercept(Invocation invocation) throws Throwable { long startTime System.nanoTime(); StatementHandler statementHandler (StatementHandler) invocation.getTarget(); BoundSql boundSql statementHandler.getBoundSql(); ParameterHandler parameterHandler statementHandler.getParameterHandler(); // 1. 拿到原生SQL可能存在换行、多个空格 String originSql boundSql.getSql(); // 2. 把 ? 占位符替换成真实参数值 String prettySql formatSql(originSql, parameterHandler.getParameterObject(), boundSql); // 3. 真正执行SQL Object result invocation.proceed(); // 4. 统计耗时 long costMs (System.nanoTime() - startTime) / 1_000_000; StringBuilder sb new StringBuilder(\n); sb.append(--------------- MyBatis SQL Log ---------------\n); sb.append(SQL : ).append(prettySql).append(\n); sb.append(Cost : ).append(costMs).append( ms\n); sb.append(-----------------------------------------------); log.debug(sb.toString()); return result; } /** * 核心把SQL中的问号占位符替换为真实参数值 */ private String formatSql(String sql, Object parameterObject, BoundSql boundSql) { ListParameterMapping parameterMappings boundSql.getParameterMappings(); if (parameterMappings null || parameterMappings.isEmpty()) { return sql; } StringBuilder builder new StringBuilder(sql.length() 64); int index 0; for (ParameterMapping mapping : parameterMappings) { String propertyName mapping.getProperty(); Object value getParamValue(parameterObject, propertyName); // 找到下一个问号的位置 int qMarkIndex sql.indexOf(?, index); if (qMarkIndex 0) { break; } // 拼接问号之前的SQL片段 builder.append(sql, index, qMarkIndex); // 把问号替换为参数值 builder.append(formatValue(value)); index qMarkIndex 1; } // 拼接剩余部分 builder.append(sql.substring(index)); return builder.toString(); } /** * 从参数对象中按属性名取值兼容Map、POJO、单参数三种情况 */ private Object getParamValue(Object parameterObject, String propertyName) { if (parameterObject null) { return null; } // 情况1单参数且没有Param此时parameterObject就是那个参数本身 if (parameterObject instanceof String || parameterObject instanceof Number || parameterObject instanceof Boolean || parameterObject instanceof Date) { return parameterObject; } // 情况2Map类型如 Param(id) 或通过param1、param2访问 if (parameterObject instanceof Map) { Map?, ? map (Map?, ?) parameterObject; if (map.containsKey(propertyName)) { return map.get(propertyName); } // 兼容 MyBatis 自动生成的 param1、param2 for (Map.Entry?, ? entry : map.entrySet()) { if (propertyName.matches(param\\d) entry.getKey().equals(propertyName)) { return entry.getValue(); } } return null; } // 情况3普通POJO对象用MetaObject反射取属性值 try { MetaObject metaObject SystemMetaObject.forObject(parameterObject); Object value metaObject.getValue(propertyName); return value; } catch (Exception e) { return null; } } /** * 把参数值格式化成可直接执行的SQL片段 */ private String formatValue(Object value) { if (value null) { return NULL; } if (value instanceof String) { return escapeQuotes((String) value) ; } if (value instanceof Character) { return value ; } if (value instanceof Date) { return new SimpleDateFormat(yyyy-MM-dd HH:mm:ss).format(value) ; } if (value instanceof Boolean || value instanceof Number) { return value.toString(); } // 其他类型如LocalDateTime、枚举、BigDecimal等 return value.toString() ; } /** * 转义SQL字符串中的单引号避免拼接出来的SQL语法错误 */ private String escapeQuotes(String str) { return str.replace(, ); } Override public Object plugin(Object target) { return Plugin.wrap(target, this); } Override public void setProperties(Properties properties) { // 留空预留做配置扩展 } }重点讲讲这段代码里两个容易被忽略细节。第一参数取值为什么用MetaObjectMyBatis内部就是靠MetaObject这个反射工具来操作参数对象的我们直接用它能保证兼容性。如果你的参数是个POJO比如UserQuery里面有name、status字段那在XML里写#{name}时propertyName就是nameMetaObject.getValue(name)就能拿到值。如果你的参数是Map那更直接map.get(name)就行。第二为什么参数值要转义单引号拼接SQL日志本质上是“把值渲染到SQL字符串里”如果参数本身带了一个单引号比如搜索关键词obrien不转义拼出来的SQL就是WHERE name obrien拿到Navicat里一执行直接报错。转义成obrien就合法了。注意这只是在日志里做转义展示不代表SQL执行本身有问题真正的执行永远走PreparedStatement参数绑定没有注入风险。3.3 输出格式与启动开关设计截至这里最核心的日志已经能打出来了。但生产环境直接用log.debug会有个问题线上日志级别一般调到info你这条SQL日志就彻底消失了。想用的时候翻不出来是个麻烦事。我的做法是加一个开关用 Spring Boot 的ConfigurationProperties或Value控制。Component public class SqlLogProperties { // 是否打印SQL日志默认false Value(${mybatis.sql-log.enabled:false}) private boolean enabled; // 查询超过多少毫秒才打印默认500ms Value(${mybatis.sql-log.slow-threshold:500}) private long slowThreshold; // getter / setter ... }然后在拦截器里注入这个配置if (!properties.isEnabled()) { // 没开开关直接执行不打日志 return invocation.proceed(); }再配合一个“慢SQL阈值”的概念平时不开日志但某一天线上出了慢SQL你把这行配置打开mybatis.sql-log.enabledtrue mybatis.sql-log.slow-threshold200重启应用所有执行超过200ms的SQL都会打出来。这比盲目打开debug日志翻大海捞针舒服太多。也可以在intercept方法里判断costMs slowThreshold用log.warn打印既不影响正常SQL输出又能精准抓出慢SQL。3.4 和PageHelper、MyBatis-Plus共存的经验我项目里同时用了PageHelper分页插件和MyBatis-Plus这两个框架本身也都是靠拦截器实现的。PageHelper的PageInterceptor就是拦截了Executor的query方法在查询之前把分页参数塞进BoundSql拼上LIMIT语句。我的SqlLogInterceptor拦截的是StatementHandler.prepare这个位置在PageInterceptor的“下游”。也就是说PageHelper拼好分页SQL之后我这边再打日志打出来的SQL天然就是带LIMIT的最终版本这反而是好事。不过有几个注意点第一拦截器顺序问题。如果你同时有多个拦截器都拦StatementHandler它们的执行顺序靠Intercepts里配置的顺序是不完全可靠的主要取决于注册顺序。必要时候可以在intercept里手动判断是不是Invocation.getTarget()已经被包了一层防止重复打印。第二MyBatis-Plus的selectById、selectPage也会经过这套拦截器所以日志会把这些自动生成的SQL也打出来这是正常的。如果你想区分“手写SQL”和“MP自动SQL”可以反射拿MappedStatement.getId()里面是接口全限定名.方法名按Mapper接口路径过滤。第三MyBatis-Plus的逻辑删除是改SQL实现的如果你开了逻辑删除拦截器打印出来的完整SQL里会包含deleted0这种条件这也不是问题反而是调试逻辑删除时很实用的能力。4. 上线之后必踩的几个坑我已经替你们踩过了4.1 参数拼接时类型不对SQL拿到数据库根本跑不了第一个坑就是Date类型格式化。MyBatis里Date对应的JDBC类型可能是Date、Time、Timestamp直接toString()会打出一坨2024-01-01 10:20:30.123有些数据库客户端还不认。所以代码里统一转成yyyy-MM-dd HH:mm:ss格式最稳妥。第二个坑是LocalDateTime。现在新项目基本都用java.time包如果你参数里有LocalDateTime它走的是toString()打出来是2024-01-01T10:20:30中间那个T让很多数据库工具识别不了。处理方式是在formatValue里增加LocalDateTime、LocalDate、LocalTime的判断统一转成带秒的字符串。第三个坑是BigDecimal。这个类型本身不会报错但如果你拿去和数据库字段做比较精度问题会让人很困惑。日志里打出来是1000.00数据库里存的是1000看起来长得不一样其实值相等这个不需要处理只是心里要有数。4.2 foreach动态SQL导致问号数量对不上这个坑我记忆犹新。有一次排查SQL日志打出来是SELECT * FROM user WHERE id IN (?, ?, ?)但我的拦截器只替换了第一个问号后面的?原样打出来了。原因出在formatSql方法的逻辑上foreach标签在MyBatis解析的时候会把每个元素生成一个独立的ParameterMapping同时SQL里有几个问号parameterMappings列表就有几个元素所以理论上按顺序替换不会出问题。但有一种情况会出问题如果你在SQL里用了${}拼接比如foreach collectionids open( separator, close)${item}/foreach那占位符?的数量就和ParameterMapping对不上了因为这走的是字符串直接替换不走预处理。这时候你拼出来的日志可能问号数量不等于参数数量。解决办法是在formatSql里加入一个保护如果parameterMappings.size()和sql中?数量不一致就把原始SQL原样返回宁可看原生SQL也不要打断拦截器本身的执行。int placeHolderCount countPlaceHolders(sql); if (placeHolderCount ! parameterMappings.size()) { log.warn(SQL占位符数量和参数映射数量不一致返回原始SQL); return sql; }4.3 敏感字段脱敏与日志级别控制这是生产环境很现实的问题。你打了完整SQL日志意味着手机号、身份证号这些参数也会原样打进日志文件。如果一个实习生拿着日志文件拷走了一份就是一次数据安全事故。我的实践是在formatValue里加一个脱敏开关对匹配到手机号、身份证号、银行卡号正则的参数做打码处理private String maskSensitiveData(String value) { if (value null) { return null; } // 手机号保留前3后4中间打码 if (value.matches(1\\d{10})) { return value.substring(0, 3) **** value.substring(7); } // 身份证保留前4后4中间打码 if (value.matches(\\d{15}(\\d{2}[0-9Xx])?)) { return value.substring(0, 4) ******** value.substring(value.length() - 4); } return value; }脱敏之后的SQL虽然不能直接拿去数据库跑了但依然能看到参数的轮廓对排查帮助也够。如果你需要完整SQL去复现问题可以单独在测试环境打开“不脱敏”开关。另外日志级别真的要控制好。我的习惯是默认debug级别输出生产环境日志级别是info所以平时这些SQL日志完全不会落盘。只有排查问题时才把开关打开或者把日志级别临时调低。千万不能把SQL日志放在info级别长期开着大数据量下日志文件几天就能写满几个G。4.4 常见问题速查表把这段时间遇到的和网友反馈的问题统一整理成一张表。现象可能原因解决方法拦截器完全不生效Signature的args写错如写了基本类型查看MyBatis源码确认prepare方法签名改对参数类型拦截器生效但日志里参数全是nullgetParamValue取不到值通常是单参数无Param的场景在getParamValue里先判断parameterObject是不是基本类型是就直接返回它本身SQL拼出来无法在Navicat执行Date、LocalDateTime 格式化问题或字符串没加引号/没转义统一在formatValue里处理类型字符串加引号并转义单引号foreach生成SQL问号数量对不上${}和#{}混用或动态SQL拼接导致占位符和参数映射错位加countPlaceHolders保护数量不一致时返回原始SQL打出的SQL和实际执行的不一样拦截器选的时机太早比如拦了Executor.query但上面还有别的插件在改SQL改成拦StatementHandler.prepare拿到的是最终给JDBC的SQLPageHelper分页SQL没打全拦截器执行顺序在PageHelper之前用InterceptorChain确认顺序或者把自定拦截器注册顺序调整到分页插件之后日志文件过大磁盘告警SQL日志级别长期在info或更高改为debug级别加“开启开关”平时关闭5. 这样写好之后还能顺手扩展出哪些高级玩法5.1 慢SQL自动告警日志打印只是第一步。既然在intercept里已经算出了costMs加一个阈值判断超过多少毫秒就发一条告警到企业微信/钉钉是很自然的事。if (costMs properties.getSlowThreshold()) { String msg 慢SQL告警 \n prettySql \n耗时: costMs ms; log.warn(msg); // 调用通知客户端推送告警 notifyService.send(msg); }我实际用下来这个能力几乎零成本但价值非常大。不用再专门搭一套慢SQL监控平台直接基于现有拦截器就能捕捉到所有性能异常。缺点是要注意告警逻辑不能阻塞主流程一定异步发送别让一条SQL日志影响了业务性能。5.2 数据权限自动拼接过滤条件如果说日志是“看”那拦截器还能做到“改”。很多系统要求“只能看自己部门的数据”最常见实现是在Mapper XML里手动拼dept_id ?漏了一个Mapper就是安全隐患。用拦截器可以在StatementHandler执行前通过BoundSql反射修改SQL自动追加AND dept_id ?参数。这个玩法要慎重因为反射改BoundSql里的SQL是动框架内部的final字段需要用到特定的反射技巧而且和分页插件、逻辑删除插件混用时容易出问题。我的建议是新手不要往这个方向踩先把日志做好数据权限优先用MyBatis-Plus的TenantLineInnerInterceptor这种官方插件只有在架构复杂到官方插件覆盖不了时才考虑用自定义拦截器做。5.3 按Mapper开关按耗时裁剪最后一个很实用的点子是让日志按“维度”裁剪不然项目大了日志会特别吵。比如只打印某个接口的SQLmybatis: sql-log: enabled: true include-mappers: - com.example.mapper.OrderMapper - com.example.mapper.UserMapper实现方式很简单MappedStatement.getId()返回的是类似com.example.mapper.OrderMapper.selectOrderList的字符串在intercept里判断是否命中前缀就行。这样你可以只盯着某个出问题的Mapper慢慢看其他SQL全部静默。如果你的项目里查询量大还可以加一个“只打印超过N行的SQL”的开关避免SELECT * FROM log_table这种返回几万行的日志把终端刷爆。这些都是很小的改动但能让这套拦截器真正“私有化”成你自己的工具。6. 写在最后的个人体会拦截器写完用了差不多一个月我最大的感受是日志工具最值钱的部分不是代码是你在排障时节省下来的时间。以前看到一个慢SQL要手动拼参数、连客户端、跑EXPLAIN现在日志直接给我一条能跑的SQL复制、执行、看执行计划三步走完。尤其接手别人的老项目时一个干净的SQL日志拦截器能让你的上手效率翻倍。最后再分享一个小技巧在formatSql拼接之前手动把SQL里的换行替换成空格日志看起来会舒服很多。比如拿到原始SQL里面有十几个换行打印出来的多行SQL在终端里是很占空间的一条replaceAll(\\s, )就能让日志变成一行完整SQL读取效率会高很多。这个细节我是在用了两个星期后才想到的加了之后同事都来问我配置文件在哪原来他们早就嫌多行日志碍眼了。
返回列表