MyBatis Plus SQL日志配置实战:从零开始打开与调优
接手一个老项目接口慢得离谱想看看底层 SQL 到底长什么样结果控制台干干净净一条日志都没有。翻配置文件发现 yml 里只写了几句logging.level.root: info根本没有 MyBatis 相关的配置于是折腾了半天最后才算把 MyBatis Plus 的 SQL 日志完全打开。这篇文章就把我这次配置的全过程、踩过的坑和最终的实践建议一起写出来适合刚接手 MyBatis Plus 项目、或者配置了日志却发现怎么都不生效的开发者。内容不涉及太深原理都是日常干活直接能用的东西。1. 先说清楚日志不打印问题往往出在哪1.1 打印SQL日志到底有什么用很多人一开始不理解ORM 框架自动生成的 SQL 有什么好看的等你真遇到问题就知道MyBatis Plus 的动态 SQL 是根据条件、注解、Wrapper 等一堆逻辑拼出来的代码层面看到的只是queryWrapper的一堆规则真正落到数据库的 SQL 是什么样不打开日志完全看不到。举几个我实际遇到的场景。某次联调前端传入一个筛选条件后端查出来的数据始终多一行怎么检查 Service 逻辑都看不出问题。最后打开 SQL 日志发现or和and拼接时优先级不对MyBatis Plus 生成了一条多了一个OR条件的 SQL把不该查的行带出来了。还有一次是分页查询突然失效接口结果越查越多日志里看到根本没有LIMIT语句后来才定位到是分页插件没有注册成功。除了排查问题日常开发也能用到。比如你写了一个updateById担心它真的把某些字段更新成null了SQL 日志里清清楚楚地能看到 SET 子句到底包含了哪些字段。再比如联调阶段要确认参数是否绑定正确看Parameters那一行就行。总之SQL 日志相当于炒菜时的火候指示灯看不到它你永远只能靠猜。1.2 三个最容易被忽略的前提配置不生效百分之八十都是下面三个原因。第一配置文件键名不对。很多人会把mybatis-plus.configuration.log-impl误写成mybatis.configuration.log-impl或者把log-impl写成logImpl、sql-log。前者是原生 MyBatis 的配置后者是网上各种老文章里抄来的错误写法。MyBatis Plus 的官方配置路径就是mybatis-plus.configuration.log-impl要严格按这个来。第二日志实现类决定了日志归谁管。如果你在配置里写的是StdOutImplSQL 日志会直接打到标准控制台不走 Spring Boot 的日志体系。这时候你调logging.level是完全没用的因为它根本不经过Logger。只有把日志实现换成Slf4jImplSQL 日志才会进入 slf4j 体系才能被日志框架统一管理。第三版本差异。MyBatis Plus 从 3.x 到现在 3.5.x配置类发生过不少调整网上很多教程讲的是老版本写法拿到新版本上就可能失效。最靠谱的办法是打开你自己项目里mybatis-plus-spring-boot-starter的 jar 包找到自动配置类看它到底读取哪个配置项或者直接查看对应版本的官方文档页。这三个前提没搞清楚后面的配置怎么写都可能翻车。2. 最省事的两种配置方式照着抄就行2.1 方式一stdout直接输出适合本地调试如果你只是本地联调想看 SQL最快的方式是在application.yml里写mybatis-plus: configuration: log-impl: org.apache.ibatis.logging.stdout.StdOutImpl这一行配置的意思是说让 MyBatis 在打印 SQL 时使用StdOutImpl这个日志实现类。这个类的逻辑很简单直接把格式化好的 SQL 输出到System.out所以你在 IDEA 的控制台立刻就能看到类似这样的内容Creating a new SqlSession SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession5f9e5a3] was not registered for synchronization because synchronization is not active JDBC Connection [com.zaxxer.hikari.pool.HikariProxyConnection4a377fdb wrapping com.mysql.cj.jdbc.ConnectionImpl1a2b3c4d] will not be managed by Spring Preparing: SELECT id,name,email FROM user WHERE id? Parameters: 1008(Long) Total: 1这种方式的好处是零成本、立刻见效没有任何日志框架的介入所以不用担心日志依赖冲突之类的问题。但它也有明显的短处既然不经过日志框架你就没法控制它的输出级别生产环境开了就直接刷屏也没法写到独立文件里做持久化排查更没法根据包路径做精细化的开关。所以我的用法是本地临时开着联调完就关掉。它适合我就想马上看一眼 SQL不适合我要把 SQL 日志纳入项目日志体系。2.2 方式二接入slf4j统一日志适合所有环境推荐的做法是接入 SLF4J让 SQL 日志和项目里其他日志走同一个框架。配置如下mybatis-plus: configuration: log-impl: org.apache.ibatis.logging.slf4j.Slf4jImpl logging: level: com.example.demo.mapper: debug这里有两部分。第一部分是把 MyBatis 的日志实现切换为Slf4jImpl这样 MyBatis 向外输出日志时会委托给org.slf4j.Logger。第二部分是设置日志级别com.example.demo.mapper要换成你自己项目里 mapper 接口所在的包路径。为什么必须是debug因为 MyBatis 打印 SQL 时使用的日志级别就是DEBUG。如果你把包级别设成infoSQL 日志就不会显示。这一点经常被忽略有人配置了Slf4jImpl但logging.level写的是info结果控制台啥也没有还以为是配置有问题。这种方式最灵活SQL 日志会出现在工程统一的日志文件里也可以单独拆出来可以被logging.level精确控制生产环境也可以通过改配置实时关闭不用重新发布。2.3 两种方式的本质区别用一张表看对比对比项StdOutImplSlf4jImpl logging.level输出位置仅控制台标准输出日志框架统一输出可控制台/文件/远程受 logging.level 控制不受控制受控制可按包精确调整日志框架依赖无依赖依赖 SLF4J 绑定本地联调极简单稍微多两行配置生产环境不建议可按需安全开/关能否输出到文件不能可以两者本质上是 MyBatisLogFactory在创建日志适配器时选择了不同的实现类。StdOutImpl内部直接把消息丢给System.out.println而Slf4jImpl是把消息交给 SLF4J 门面再由底层绑定到 Logback、Log4j2 等具体实现。说白了前者是直接喊后者是通过总机转接。我给大多数项目的建议是直接用第二种。哪怕你是个纯个人项目也建议用 Slf4jImpl因为随着项目变大迟早会遇到我要把某几个 mapper 的 SQL 输出到单独文件这种需求到时候再改配置就是一个字段的事但排查日志依赖可能会花上半天。3. 日志集成与环境隔离让SQL日志听话3.1 按 mapper 包定向控制日志级别如果项目里 mapper 很多全项目统一开debug会让日志量瞬间暴涨尤其是那些有循环查询的接口一秒几百条 SQL 刷屏连业务日志都被淹没。这时候最好的做法是按包定向控制。logging: level: com.example.demo.mapper: debug com.example.demo.mapper.statistic: info com.example.demo.service: info这样做的好处是职责清晰需要排查的模块开debug稳定的模块保持info日志量完全可控。甚至可以只针对单个 Mapper 接口打开logging: level: com.example.demo.mapper.UserMapper: debug注意这里要用 Mapper 接口的全限定名甚至可以理解为这个接口对应的日志器名称。MyBatis 在打印 SQL 时logger 的名字就是mapper接口的全限定名 当前方法名所以你定向到类就能控制类里的所有方法定向到包就能控制包下所有 Mapper。还有一个细节即使你不显式配置log-impl只要项目里有 SLF4J 绑定MyBatis 通常也会自动探测到 SLF4J 并启用此时logging.level依然可以控制 SQL 日志。但这个自动探测在不同版本、不同依赖组合下行为不完全一致为了不给排查留隐患我都会显式写明Slf4jImpl把不确定性干掉。3.2 不同环境下的开关策略很多项目只有一个application.yml里面配了logging.level...: debug结果发到生产环境也在打印 SQL。生产环境打印所有 SQL 的问题不只是刷日志还有数据安全隐患查询条件里的手机号、身份证号、订单号全部明文落到日志文件里这玩意儿要是日志被脱库或者被第三方拿到妥妥的泄露事故。我习惯按 profile 拆分配置。开发环境# application-dev.yml mybatis-plus: configuration: log-impl: org.apache.ibatis.logging.slf4j.Slf4jImpl logging: level: com.example.demo.mapper: debug生产环境# application-prod.yml mybatis-plus: configuration: log-impl: org.apache.ibatis.logging.nologging.NoLoggingImplNoLoggingImpl是 MyBatis 自带的空实现会把日志全部吞掉。这样 SQL 日志在生产环境完全关闭零输出没有任何性能损耗。等线上出问题时再临时把这一行改回Slf4jImpl并配合按包开debug发布一版用完再撤回去。如果你用的配置中心那就更简单了直接在配置中心里加一个开关字段来控制log-impl的值就行。注意改log-impl必须重启应用才能生效它不是 Spring 配置里可以热更新的日志级别因为LogFactory是在 MyBatis 初始化阶段创建的。3.3 配合 Logback 做独立的SQL日志通道日常联调阶段我们经常要把 SQL 日志单独抽到文件里方便事后翻查。常见的 Logback 配置appender nameSQL_FILE classch.qos.logback.core.rolling.RollingFileAppender filelogs/sql.log/file rollingPolicy classch.qos.logback.core.rolling.TimeBasedRollingPolicy fileNamePatternlogs/sql.%d{yyyy-MM-dd}.log/fileNamePattern maxHistory30/maxHistory /rollingPolicy encoder pattern%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n/pattern /encoder /appender logger namecom.example.demo.mapper leveldebug additivityfalse appender-ref refSQL_FILE/ /logger这里最重要的一个属性是additivityfalse。如果你不关掉 additivitymapper 包下的 logger 除了输出到SQL_FILE还会把日志继续向 root logger 传播结果就是 SQL 日志在控制台和文件里各出现一次看着很乱。关掉之后SQL 日志就只进入SQL_FILE这个管道。需要注意路径问题logs/sql.log是相对启动目录的如果你用 Docker 部署一定要把/app/logs挂载到宿主机目录否则容器一重启文件就丢了。如果是本地调试最好设置成绝对路径。独立文件的好处是排查 slow query 或特定用户的问题时直接grep这个文件就行不用在生产日志里海量搜。4. 看懂SQL日志Preparing 和 Parameters 到底在说什么4.1 一条完整SQL日志长什么样打开了日志很多人看到这几行就犯迷糊咱们拆开看。 Preparing: SELECT id,name,phone,status FROM user WHERE id? AND status? Parameters: 1008(Long), 1(Integer) Total: 1第一行的Preparing就是 MyBatis 告诉数据库我要执行一条预编译 SQL后面跟的是 SQL 模板。注意这里用的是问号占位符SQL 并没有真正拼上参数值。这是 JDBC 里标准的PreparedStatement预编译机制目的有两个一是防止 SQL 注入数据库会把整个模板编译好参数只作为纯值传入二是数据库可以复用执行计划性能更好。第二行Parameters是 MyBatis 实际绑定的参数列表每个参数都会标注类型。1008(Long)表示第一个?绑定的是 Long 类型的 10081(Integer)表示第二个?绑定的是 Integer 类型的 1。你看到的?顺序和这里参数的顺序是一一对应的。如果这里出现null说明你传入的参数是 null很多空指针问题在这里一眼就能看出来。第三行Total表示这次查询返回的结果条数。对于update或delete它显示的是受影响的行数。比如你执行updateById想确认是否真的更新了记录看这个数字就行。如果update的Total是 0说明主键没匹配上那大概率又是人为的 bug。还有一个常被问的点上面还有个 Total前面的耗时去哪了MyBatis 原生日志不会直接打印执行耗时只有通过性能分析插件或第三方拦截器才能看到。如果你特别在意每条 SQL 的执行时间等下看 6.1 节。4.2 打印真实执行SQL的两种额外方案Preparing和Parameters分开打印的设计很好但有时候你需要看到真实的完整 SQL也就是把参数填充进去的语句。这里有两种额外方案。第一种是使用 p6spy。p6spy 是一个 JDBC 层的代理工具它在数据库驱动之上做了一层拦截日志里可以直接输出参数替换后的完整 SQL还能带执行耗时。配置思路大概这样引入依赖后准备一份spy.propertiesappendercom.p6spy.engine.spy.appender.Slf4JLogger logMessageFormatcom.p6spy.engine.spy.appender.SingleLineFormat databaseDialectmysql autoflushtrue然后把数据源地址改成 p6spy 的前缀spring: datasource: url: jdbc:p6spy:mysql://localhost:3306/demo driver-class-name: com.p6spy.engine.spy.P6SpyDriver这样日志里出现的不再是?而是SELECT id,name FROM user WHERE id1008这样的完整 SQL。需要注意的是 p6spy 有额外的性能损耗每条 SQL 都要经过代理层做日志格式化所以生产环境不建议开。第二种方案是打开数据库自身的general_log例如 MySQL 的通用日志。它能记录所有到达数据库的语句但也把其他来源的语句全记录了日志量极大而且生产环境开 general_log 对磁盘和 [ ] 性能都是负担只建议在本地排查疑难杂症时临时使用。日常开发我推荐直接看 MyBatis 的PreparingParameters完全够用。只有当你需要精确分析某条 SQL 性能时才临时用 p6spy 把它打开用完立刻关掉。5. 踩坑实录配置不生效的典型现场5.1 配置键拼写与版本差异第一个坑是最常见的配置了log-impl但 SQL 日志死活不出来。网上随便一搜能搜到各种五花八门的写法有mybatis-plus.sql-log: true的有mybatis-plus.log-impl的还有mybatis-plus.configuration.logImpl这种驼峰写法。先说结论以官方文档为准MyBatis Plus 3.x 的正确写法就是mybatis-plus: configuration: log-impl: org.apache.ibatis.logging.slf4j.Slf4jImpl关于驼峰还是短横线mybatis-plus.configuration.logImpl这种写法在 Spring Boot 的松散绑定下通常也能生效但不同版本行为不完全一致。老项目里有时候会因为自定义了配置类导致绑定不上我用log-impl这种短横线写法到现在没有翻过车。另外要特别注意mybatis-plus.sql-log: true这种写法是某些老教程里想当然的配置根本不在此处生效。如果你项目里还有旧版的mybatis-plus-boot-starter和mybatis-plus-extension混用配置类读取的配置项可能都不一样这时候最好统一为一个 starter 版本比如mybatis-plus-spring-boot-starter。排查方法很简单打开 jar 包里MybatisPlusProperties类看看字段上标注的ConfigurationProperties前缀和字段名再对照自己的 yml。自己直接读源码比在网上搜任何答案都可靠。5.2 自定义 SqlSessionFactory 导致配置丢失有些项目为了做特殊配置会手动创建 SqlSessionFactoryBean public SqlSessionFactory sqlSessionFactory(DataSource dataSource) throws Exception { MybatisSqlSessionFactoryBean factoryBean new MybatisSqlSessionFactoryBean(); factoryBean.setDataSource(dataSource); factoryBean.setConfiguration(new org.apache.ibatis.session.Configuration()); return factoryBean.getObject(); }这种写法会让 Spring Boot 对 MyBatis Plus 的自动配置失效因为你完全自己控制了一个Configuration。你新建的这个Configuration是裸的没有经过 MP 的自动配置流程log-impl配置自然就没被读进去。表现就是你明明在 yml 里写了log-impl: Slf4jImpl但 SQL 日志还是不出来或者 mapper 下划线转驼峰等功能也莫名其妙失效。解决办法有两个。一是不要手动创建 SqlSessionFactory让 MyBatis Plus 的自动配置去生成关键配置全部写在 yml 里。二是如果真的需要自定义就在你手动创建的时候把配置项同步进去比如设置一下日志实现org.apache.ibatis.session.Configuration configuration new org.apache.ibatis.session.Configuration(); configuration.setLogImpl(org.apache.ibatis.logging.slf4j.Slf4jImpl.class); factoryBean.setConfiguration(configuration);但这个方法要小心setLogImpl之后你会发现就算logging.level设成 debugSQL 也不一定打印。因为 MyBatis Configuration 里有个logPrefix和logImpl的组合问题你要么在 yml 里配要么在代码里配别两边都配造成混乱。实际项目里九成不需要手动创建 SqlSessionFactory能不用就不用。5.3 日志依赖冲突与绑定异常第三种情况是依赖冲突。Spring Boot 默认用的是 LogbackSLF4J 作为门面这个组合通常没问题。但有些项目为了性能或特殊需求会额外引入slf4j-simple、log4j-slf4j-impl等实现结果启动时控制台会打出类似这样的提示SLF4J: Class path contains multiple SLF4J bindings.一旦出现多绑定MyBatis 在调用 SLF4J 时具体走了哪个实现就不可控了SQL 日志可能出现在控制台也可能跑到奇怪的位置甚至干脆没有输出。这种情况的根治方法是清理依赖保留一个日志实现就够。用 Maven 的话用mvn dependency:tree看一下是谁引入了多余的绑定然后在对应依赖上排除掉。还有一个隐蔽的问题项目里本身没有任何日志实现时MyBatis 的LogFactory在启动时会逐个探测可用日志组件探测不到就 fallback 到NoLogging也就是所有日志都静默。在 Spring Boot 场景不太可能出现但如果你写了一个非 Spring Boot 的简单工具只引了mybatis-plus没引日志可能就是这个结果。此时logging.level配得再好也没用先把日志实现依赖补上。6. 进阶玩法慢SQL、多数据源与日志安全6.1 慢SQL发现与性能拦截器前面说过MyBatis 原生日志不输出每条 SQL 的耗时。但实际排查性能问题的时候我们希望超过阈值的 SQL 能单独被标记。MyBatis Plus 提供了性能分析相关的 InnerInterceptor不同版本类名有一定差异我以常见版本为例Bean public MybatisPlusInterceptor mybatisPlusInterceptor() { MybatisPlusInterceptor interceptor new MybatisPlusInterceptor(); // 部分版本叫 PerformanceInnerInterceptor部分版本叫 PerformanceAnalyzer // 具体以你本地 jar 包里实际类名为准 interceptor.addInnerInterceptor(new PerformanceInnerInterceptor()); return interceptor; }配置之后通过日志可以输出每条 SQL 的执行耗时比如[Performance] SQL: SELECT * FROM user WHERE id1008 Time: 1023 ms如果超过默认阈值还会输出更醒目的 block 日志。这套机制适合开发环境调优用。注意一点这类性能插件本质上是给 SQL 执行加了一层拦截对极端性能敏感的业务有微小损耗生产环境可以关闭。如果想在生产环境长期监控慢 SQL建议交给 APM 系统和数据库自带的慢查询日志而不是依赖应用层拦截器。另外一个实用小习惯是平时开着 MyBatis 的Total日志遇到某个接口耗时严重第一反应就是翻 SQL 日志看看是不是出现了循环查询、大查询或者是没有走索引的查询。SQL 日志 数据库EXPLAIN组合定位问题比瞎猜快得多。6.2 多数据源场景下的日志区分多数据源项目里SQL 日志同样可以按包区分。假设你有主、从两个数据源对应两个不同的 mapper 包logging: level: com.example.demo.mapper.primary: debug com.example.demo.mapper.secondary: warn这样主库的 SQL 日志能看到从库的 SQL 日志不输出排查问题时不至于混在一起。但如果两个数据源共用同一个 mapper 接口比如用某个动态数据源组件根据DS注解切换数据源那 SQL 日志在输出时都出自同一个 logger就不好区分了。此时我一般是临时在 Service 层打一条日志标识当前线程用的是哪个数据源再通过执行顺序把 SQL 日志串起来。如果你用的是动态数据源框架通常它自己会在切换数据源时输出提示日志结合起来看也行。多数据源场景更要注意的是把log-impl设置为Slf4jImpl后数据源切换的日志和 MyBatis SQL 日志都会进入同一个日志体系建议在日志 pattern 里加上线程名。SQL 日志的输出中[http-nio-8080-exec-3]这个线程标识对于按请求追查非常有价值。6.3 敏感参数与链路 traceId 的日志实践SQL 日志里能看到的参数往往很敏感。一个查询用户订单的接口可能把手机号、身份证号全部打出来。本地开发无所谓生产环境如果长期开着debug这些明文数据就留在了日志文件里一旦日志被导出或泄露就是安全事故。所以生产环境要么直接把log-impl设为NoLoggingImpl要么开debug但只开个别必要接口且明确设置日志文件的访问权限。如果你的业务确实需要在生产环境打印部分 SQL而对参数脱敏有硬性要求可以考虑在日志框架层面对包含敏感参数的日志做替换。简单思路是在 Logback 的 Encoder 层写一个自定义过滤器匹配Parameters行中的手机号规则替换成1************。这个方案不完美但对降低泄露风险是有意义的。另一个更彻底的方向是使用自定义类型处理器或在业务层对查询条件做限制让敏感参数本身就不出现在 SQL 里。另外微服务链路追踪场景下我觉得很有价值的一个实践是给日志 pattern 加上 traceId。比如用 Logback patternpattern%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] [%X{traceId}] %-5level %logger{50} - %msg%n/pattern这样 SQL 日志会和上半场的业务日志串到同一个 traceId 下。排查问题时拿一个用户请求的 traceId能一口气拉全这个请求经历的所有服务、所有 SQL效率提升不止一个量级。如果你用链路组件它会自动往 MDC 里塞 traceId你要做的只是把%X{traceId}写进 pattern。最后分享一个我的个人习惯。每次开工新需求我先把 yml 里的 mapper 包日志开到 debug联调通过再关掉或者改成 info 收工。这个习惯帮我避免了很多本地跑不通、前端等着看效果、后端不知道数据从哪来的尴尬时刻。SQL 日志这种东西配置上花五分钟调稳后面省下来的可能就是几个小时的排查时间值得每个做后端的人认真对待。