ARTICLE DETAIL

资讯详情

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

MyBatis Plus SQL日志打印全攻略:参数替换与慢SQL排查实践

MyBatis Plus SQL日志打印全攻略:参数替换与慢SQL排查实践 排查数据库问题时看不到完整SQL是件极其痛苦的事情。MyBatis Plus把SQL语句和参数分两处打印日志一多根本对不上号线上出个慢查询想确认到底执行了什么语句翻日志却发现只有一行“Preparing: SELECT...”加一行“Parameters: 1, 2, 3”完全没法直接复制去数据库执行。这篇文章就来系统地整理MyBatis Plus打印SQL日志的完整知识包含实现方式、具体配置、参数占位符转真实值方案、生产环境的坑以及我实际踩过的一些问题。适合所有使用MyBatis Plus做持久层开发的Java后端工程师不管是刚接触框架没多久的初级开发还是已经写了多年业务代码的老手都能从中找到能直接用上的内容。1. 为什么SQL日志如此关键以及MyBatis Plus默认的日志机制1.1 SQL日志在开发和排障中的真实价值很多业务问题归根结底就是“执行的SQL和想的不一样”。举个我处理过的真实案例某次线上订单金额对不上业务同学查了半天代码逻辑发现一处条件判断写反了但真正让人崩溃的是MyBatis Plus生成的SQL带有WHERE deleted 0这个逻辑删除条件代码里明明没写SQL里却多出来让人一度怀疑是不是框架有bug。当时如果SQL日志清晰可见一眼就能定位是TableLogic注解的全局逻辑删除配置生效了根本不需要翻源码。这就是SQL日志最大的价值——把框架帮你做的事、你又看不见的事全部摊开在阳光下。具体来说SQL日志帮助你实现以下几个核心目标验证动态SQL拼接是否正确MyBatis Plus的QueryWrapper、LambdaQueryWrapper条件拼接逻辑比较复杂eq、like、in、between等条件组合在一起是否生成了预期的WHERE子句只有看到真实SQL才能100%确认。确认参数绑定顺序和类型多个条件时参数顺序极其重要尤其是使用foreach拼接IN列表时每个参数值的索引位置对不对。定位慢SQL和性能瓶颈通过日志中SQL的执行时间配合数据库的执行计划分析能快速定位没有走索引的查询。排查结果集映射问题日志中显示了查询了哪些字段但结果对象里某些字段是null问题往往在于select的列没有涵盖对应字段。1.2 MyBatis Plus内置的SQL日志输出机制要彻底搞懂怎么配置SQL日志首先得知道MyBatis Plus是怎么输出日志的。MyBatis包括MyBatis Plus它是在MyBatis基础上的增强自身的日志输出有一套完整的抽象体系。MyBatis框架内部通过org.apache.ibatis.logging.Log接口来统一管理日志输出这个接口有一系列适配器实现分别对接Logback、Log4j2、SLF4J、JDK logging、Apache Commons Logging、Stdout等不同的日志框架。MyBatis会在启动时自动探测当前classpath下存在哪个日志框架然后选择对应的适配器。MyBatis Plus在配置文件中提供了mybatis-plus.configuration.log-impl这个配置项允许你直接指定使用哪个日志实现类来实现SQL语句的打印。常见的有这么几个配置值实现的日志框架输出效果org.apache.ibatis.logging.stdout.StdOutImplSystem.out控制台直接输出简单粗暴不带日志级别org.apache.ibatis.logging.slf4j.Slf4jImplSLF4J走统一日志门面受全局日志级别控制org.apache.ibatis.logging.log4j2.Log4j2ImplLog4j2输出到Log4j2日志系统org.apache.ibatis.logging.log4j.Log4jImplLog4j旧版Log4jorg.apache.ibatis.logging.nologging.NoLoggingImpl无不输出任何日志理解了这套机制后面所有配置就会变得非常清晰。你既可以用log-impl强制指定也可以利用MyBatis的自动探测机制完全交给日志框架的级别配置来管理。两种方式各有利弊下面详细展开。2. 打印SQL日志的三种主流实现方式2.1 方式一通过log-impl配置直接开启控制台输出最简单、最快的方案就是使用StdOutImpl。在application.yml中配置mybatis-plus: configuration: log-impl: org.apache.ibatis.logging.stdout.StdOutImpl这样配置以后所有Mapper方法执行时控制台会直接打印类似下面的内容Creating a new SqlSession SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession3f0eefde] was not registered for synchronization because synchronization is not active JDBC Connection [jdbc:mysql://localhost:3306/test?useSSLfalseserverTimezoneAsia/Shanghai, UserNamerootlocalhost, MySQL Connector/J] will not be managed by Spring Preparing: SELECT id,name,email,age FROM user WHERE (age ? AND name LIKE ?) Parameters: 20(Integer), %张%(String) Columns: id, name, email, age Row: 1, 张三, zhangsanexample.com, 25 Total: 1这种方式的优点非常明显配置简单开箱即用完全不用动日志框架的配置。项目里哪怕没有任何logback配置控制台也能看到完整SQL。但缺点同样明显所有SQL都通过System.out输出完全绕过了日志框架无法写入文件、无法按级别过滤、生产环境开启后无法灵活关闭。而且这个东西在你引入多个数据源时会发现某些情况下的连接池信息也会掺杂进来输出比较杂乱。这种方案适合什么场景呢小而快的项目、临时的本地调试。如果说你只是想快速看一条SQL长什么样那直接用这个一秒搞定不用想别的。2.2 方式二借助日志框架级别控制实现SQL输出这是我认为最正规、最推荐的方案核心思路是MyBatis Plus执行SQL时会通过SLF4J输出日志日志级别为DEBUG只需要在你项目的日志框架配置中将MyBatis的Mapper包或者MyBatis Plus相关的logger级别设置为DEBUG即可。先看MyBatis自动探测机制下它会输出哪些logger名。回想我在实际项目里看到的输出打开logback的DEBUG级别后会看到类似这样的日志logger namecom.example.demo.mapper.UserMapper levelDEBUG/这里需要解释一个细节。MyBatis的SQL日志是通过Mapper接口的完整类名作为logger name来输出的也就是说每个Mapper接口都是独立的logger。所以在日志框架里你可以精确控制“哪些Mapper打印SQL哪些不打印”这对大项目来说非常实用。采用logback配置示例!-- 控制某个具体Mapper的SQL日志 -- logger namecom.example.demo.mapper.UserMapper levelDEBUG/ !-- 控制整个包下所有Mapper -- logger namecom.example.demo.mapper levelDEBUG/如果你使用的是log4j2对应的配置为Logger namecom.example.demo.mapper levelDEBUG additivityfalse AppenderRef refConsoleAppender/ /Logger有些项目中还会见到一种更粗暴的配置将org.mybatis这个包整体设置为DEBUG级因为MyBatis内部的很多核心链路org.apache.ibatis.executor、org.apache.ibatis.session等也都有日志输出。但我不建议这么做原因在于org.mybatis包整体DEBUG输出的信息量非常大包括SqlSession的创建、事务同步注册、连接管理器处理等大量细节对你的排查并没有帮助只会刷屏。我自己的标准做法是只配置mapper包路径。这种方案的好处是完全融入项目的统一日志体系。SQL日志会和业务日志一起输出到文件带上时间戳、线程号、traceId排查问题时能串起来生产环境想关闭把级别调回INFO即可不需要改动任何代码。坏处就是要理解日志框架的配置方式不像StdOutImpl那样无脑。2.3 方式三彻底解决参数占位符问题的p6spy方案熟悉MyBatis日志的同学都知道Preparing: SELECT ... WHERE age ?打印出来的是占位符?而真实的参数值在下一行Parameters: 20(Integer)单独打出来。单条SQL还好一旦去分析慢SQL日志得手动把参数回填进SQL里才能执行非常麻烦。更重要的是你没法直接把这行SQL复制到Navicat之类的客户端里跑因为?在外部不是合法的占位符写法。p6spy可以解决这个问题。它是一个数据库连接驱动级别的代理工具拦截底层JDBC调用能够打印出已经将参数渲染进去的完整可执行SQL。它的核心原理是在JDBC驱动和你的业务代码之间增加一层代理当你的应用通过DriverManager或者DataSource获取连接时p6spy会包装一层代理连接。你的SQL执行时p6spy能拿到真实的PreparedStatement参数数组然后渲染出完整的SQL语句。具体接入步骤为第一步引入依赖dependency groupIdp6spy/groupId artifactIdp6spy/artifactId version3.9.1/version /dependency第二步在application.yml中修改数据源驱动和URLspring: datasource: driver-class-name: com.p6spy.engine.spy.P6SpyDriver url: jdbc:p6spy:mysql://localhost:3306/test?useSSLfalseserverTimezoneAsia/Shanghai username: root password: root注意驱动和URL都是成对修改的URL要在原有JDBC地址前加jdbc:p6spy:前缀且驱动要换成P6SpyDriver。第三步在classpath根目录新增spy.properties文件核心配置如下# 指定真正要驱动的JDBC驱动 driverlistcom.mysql.cj.jdbc.Driver # 日志输出到控制台 appendercom.p6spy.engine.spy.appender.Slf4JLogger # 打印可执行的SQL把参数渲染进去 logMessageFormatcom.p6spy.engine.spy.appender.CustomLineFormat customLogMessageFormat%(currentTime)|%(executionTime)|%(sql) # 是否延迟加载 deregisterDriversfalse # 是否使用日志 logReprinttrue配置完成后你在日志里会看到类似下面这种可直接执行的SQL2024-01-15 10:23:45|2|select id,name,email,age from user where (age 20 and name like %张%)这一行直接复制到数据库客户端里就能跑非常方便。但需要提醒的是p6spy的输出内容是单行格式如果SQL特别长阅读体验反而不如MyBatis自带的多行友好格式。此外p6spy多了一层代理在高频调用场景下会有微小的性能损耗本地调试完全没问题但不建议在生产环境长期开着。2.4 三种方式对比总结方案配置复杂度输出可执行SQL日志写入文件生产环境友好度适用场景log-impl: StdOutImpl最低否否差本地快速调试日志框架级别控制中否是好项目标准配置p6spy中高是是中需要真实SQL、分析慢查询3. 实操从零开始为项目配置SQL日志输出3.1 准备工作确认MyBatis Plus版本和依赖先看一眼你项目中的mybatis-plus-boot-starter版本。目前主流项目使用的版本通常有以下分支3.4.x系列如3.4.3.43.5.x系列如3.5.3、3.5.5、3.5.7不同版本在配置上几乎没有差别configuration节点下的配置项完全兼容。但有一点要注意3.5.x版本开始MyBatis Plus内部对MyBatis的依赖版本进行了升级如果你同时手动依赖了低版本MyBatis可能导致日志配置意外失效。这是我在一个老项目中遇到过的问题后面会讲。依赖示例Mavendependency groupIdcom.baomidou/groupId artifactIdmybatis-plus-boot-starter/artifactId version3.5.7/version /dependency3.2 最推荐的日志框架级别控制完整配置过程下面以Spring Boot 2.7 MyBatis Plus 3.5.7 logback为例完整展示配置过程。这个组合目前在国内企业中的应用面非常广。在src/main/resources目录下创建或确认logback-spring.xml文件并加入如下配置?xml version1.0 encodingUTF-8? configuration !-- 控制台输出 -- appender nameCONSOLE classch.qos.logback.core.ConsoleAppender encoder pattern%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n/pattern charsetUTF-8/charset /encoder /appender !-- 文件输出生产环境建议持久化 -- appender nameFILE classch.qos.logback.core.rolling.RollingFileAppender filelogs/application.log/file rollingPolicy classch.qos.logback.core.rolling.TimeBasedRollingPolicy fileNamePatternlogs/application.%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 charsetUTF-8/charset /encoder /appender !-- 关键配置定位到Mapper接口的包路径 -- logger namecom.example.demo.mapper levelDEBUG additivityfalse appender-ref refCONSOLE/ appender-ref refFILE/ /logger !-- 自定义SQL打印格式的方案见3.3 -- logger namecom.example.demo.config.MybatisSqlInterceptor levelDEBUG additivityfalse appender-ref refCONSOLE/ appender-ref refFILE/ /logger root levelINFO appender-ref refCONSOLE/ appender-ref refFILE/ /root /configuration注意几个关键点additivityfalse的含义是这条logger的输出不再向上传递给root logger避免重复打印。不加也行但如果root也是DEBUG级别就会打两遍。logger的name是Mapper接口所在的包路径不一定是com.example.demo.mapper请替换为你自己项目中的包名。levelDEBUG是关键MyBatis输出的SQL语句日志级别是DEBUG级别设为INFO的时候就看不到SQL了。Spring Boot中对应的application.yml只需要保证MyBatis Plus不做任何特殊配置或者不配置log-impl即可。因为我们要让日志框架来接管SQL输出的开关mybatis-plus: configuration: # 注意这里不要配置log-impl或者显式配置为Slf4jImpl log-impl: org.apache.ibatis.logging.slf4j.Slf4jImpl这里再补充说明一下如果log-impl配置为StdOutImpl那么上面logback中针对mapper包级别设置的DEBUG就不会生效了因为SqlSession执行的日志输出逻辑已经不走SLF4J而是直接System.out.println了。在日志框架级别控制方案中log-impl应当配置为Slf4jImpl或者干脆不配置。3.3 让日志读出完整SQL的MyBatis Plus拦截器方案可能你会觉得p6spy要改驱动和URL有时候在数据源配置复杂的环境比如多数据源中风险比较大有没有更轻量级的方案呢有那就是基于MyBatis的Interceptor接口自定义一个SQL日志拦截器。MyBatis允许你通过Intercepts注解拦截Executor或者StatementHandler层的SQL执行。在MyBatis源码中PreparedStatementHandler中的instantiateStatement等方法会获取到BoundSql这里面既包含完整的SQL模板带?也包含参数映射关系。通过分析ParameterMapping可以将参数值回填到SQL模板中生成一条“重建”的真实SQL。下面给出一个我在项目中实际使用的拦截器代码它可以把SQL和参数合并后输出为一行package com.example.demo.config; import org.apache.ibatis.executor.statement.StatementHandler; import org.apache.ibatis.mapping.BoundSql; import org.apache.ibatis.mapping.ParameterMapping; import org.apache.ibatis.plugin.Interceptor; import org.apache.ibatis.plugin.Intercepts; import org.apache.ibatis.plugin.Invocation; import org.apache.ibatis.plugin.Signature; import org.apache.ibatis.reflection.MetaObject; import org.apache.ibatis.session.Configuration; import org.apache.ibatis.type.TypeHandlerRegistry; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.stereotype.Component; import java.text.DateFormat; import java.util.Date; import java.util.List; import java.util.Locale; import java.util.regex.Matcher; Intercepts({ Signature(type StatementHandler.class, method prepare, args {java.sql.Connection.class, Integer.class}) }) Component public class MybatisSqlInterceptor implements Interceptor { private static final Logger log LoggerFactory.getLogger(MybatisSqlInterceptor.class); Override public Object intercept(Invocation invocation) throws Throwable { StatementHandler statementHandler (StatementHandler) invocation.getTarget(); BoundSql boundSql statementHandler.getBoundSql(); Configuration configuration statementHandler.getConfiguration(); String sql showSql(configuration, boundSql); log.debug(SQL: {}, sql); return invocation.proceed(); } private String showSql(Configuration configuration, BoundSql boundSql) { String sql boundSql.getSql().replaceAll([\\s], ); ListParameterMapping parameterMappings boundSql.getParameterMappings(); Object parameterObject boundSql.getParameterObject(); TypeHandlerRegistry typeHandlerRegistry configuration.getTypeHandlerRegistry(); if (parameterMappings null || parameterMappings.isEmpty()) { return sql; } for (ParameterMapping parameterMapping : parameterMappings) { Object value getValue(parameterMapping, parameterObject, configuration); if (value ! null) { String valueStr formatValue(value); sql sql.replaceFirst(\\?, Matcher.quoteReplacement(valueStr)); } } return sql; } private Object getValue(ParameterMapping parameterMapping, Object parameterObject, Configuration configuration) { if (parameterObject null) { return null; } String propertyName parameterMapping.getProperty(); MetaObject metaObject configuration.newMetaObject(parameterObject); return metaObject.getValue(propertyName); } private String formatValue(Object value) { if (value instanceof String) { return value ; } else if (value instanceof Date) { DateFormat dateFormat DateFormat.getDateTimeInstance(DateFormat.DEFAULT, DateFormat.DEFAULT, Locale.CHINA); return dateFormat.format(value) ; } else if (value instanceof Boolean) { return Boolean.toString((Boolean) value); } else { return value.toString(); } } }这段代码的逻辑大致是通过拦截StatementHandler.prepare方法拿到BoundSql然后遍历所有的ParameterMapping从参数对象中逐个取值替换SQL模板中的?。有一点必须说明这个方案只适合数值型、枚举型等简单参数复杂对象里嵌套list表达式时可能需要进一步改造。真正大型项目中仍然推荐p6spy因为它的成熟度远高于手写拦截器能覆盖99%的场景包括嵌套参数、数组参数、null值处理等。写这个方案主要是让你了解底层原理同时给某些不能引入新依赖的场景提供一个参考。3.4 从原生MyBatis使用者的角度理解log-impl的工作机制有些同学可能会问MyBatis Plus这么多配置项我到底需要掌握到什么程度其实MyBatis Plus的日志配置根子上是MyBatis框架的能力。理解MyBatis的日志输出链路就够了Mapper接口方法调用 → MyBatis的Executor执行器SimpleExecutor/ReuseExecutor/BatchExecutor → StatementHandler预编译Statement → PreparedStatementHandler#parameterize设置参数 → DefaultParameterHandler#setParameters 遍历ParameterMapping绑定参数 → 打印Preparing和Parameters日志JDBC的PreparedStatement在预编译阶段传的是SQL模板参数是后来通过setString、setInt等方法绑定进去的。所以MyBatis日志里分两行打印是合理的因为它在预编译完成后还没有参数等绑定完参数后才由DefaultParameterHandler打印参数列表。这个理解对排查参数错位的问题非常有帮助。4. 实操过程中高频踩坑记录与排查思路4.1 配置了log-impl: StdOutImpl但控制台看不到任何SQL日志遇到这种情况我建议按照下面几个方向来排查第一确认执行的操作真的走了MyBatis Plus的Mapper方法。这里有个非常常见的误解直接注入SqlRunner然后执行会绕过MyBatis的完整代理链路吗实际上SqlRunner只是封装了SqlSession操作依然会走日志链路但如果你是在外部通过JDBC直连执行SQL那当然不会打印。第二确认mybatis-plus的配置节点是否放在了正确的位置。Spring Boot 2.x项目的application.yml中我的习惯写法是mybatis-plus: configuration: log-impl: org.apache.ibatis.logging.stdout.StdOutImpl如果你的项目是一个ConfigurationProperties类来配置MyBatis Plus比如自己写了一个MybatisPlusProperties进行属性注入那就得看那个类是否生效了。大多数情况下Spring Boot的自动配置是没问题的但如果项目中存在多个SqlSessionFactory自定义配置某些配置可能被覆盖。第三查看是否有多个数据源或自定义了ConfigurationCustomizer。多个数据源的场景下通常要为每个数据源单独指定log-impl只配置在application.yml的mybatis-plus节点只对默认的数据源生效。第四检查MyBatis Plus版本和你的Spring Boot版本是否真的有兼容性问题。比较极端的是Spring Boot 3.x对应MyBatis Plus 3.5.3中MyBatis的日志初始化原理没有变化但配置方式稍有不同如果同时使用了mybatis-plus-spring-boot3-starter配置节点的前缀有了调整需要确认你使用的是正确的starter而不是旧版starter。4.2 配置了logback的mapper包DEBUG但是SQL没打印这种情况我遇到过不止一次分析下来多数是这几种原因导致的第一你的项目实际用的是log4j2而不是logback。Spring Boot的spring-boot-starter-logging默认引入logback但是如果又显式引入了log4j2依赖实际生效的日志框架是log4j2。这时候改logback-spring.xml完全没用。排查方法很简单启动时看控制台输出最上面有没有LogbackServletContextInitializer或者Log4j2LoggingSystem字样或者查看日志文件后缀是.log还是Spring Boot默认格式。log4j2的配置要写在log4j2-spring.xml中格式是Logger而不是logger。第二Spring Boot的logging.level配置优先级覆盖了你写在logback-spring.xml里的设置。正确的是logging: level: com.example.demo.mapper: DEBUG这种配置等效于logback的logger但Spring Boot在初始化时是有顺序的如果既在YAML里配置了又在logback-spring.xml里配置了后者可能在初始化阶段被覆盖。我的建议是全项目统一一种配置方式别混用。第三SQL日志输出的logger name可能不是Mapper接口的完整类名。这是知识盲区MyBatis在打印SQL时用到的Logger名称默认取自MapperRegistry中注册的Mapper类型这个类型名就是所有的MapperScan扫描到的接口。但有一种情况例外如果项目里同时存在mybatis.mapper-locations配置且Mapper XML使用了自定义命名空间那么Executor一层的SQL日志使用的logger是mapper接口全名但并不是每个版本的MyBatis Plus都如此有些版本会使用MybatisLogger。这就需要你自己起一条测试SQL用org.slf4j.LoggerFactory.getLogger来试验Logger logger LoggerFactory.getLogger(com.example.demo.mapper.UserMapper); logger.debug(test sql log);如果这条自定义DEBUG日志能打出来说明框架日志级别配置是通的如果不能说明是日志配置本身的问题。4.3 日志打印了Preparing和Parameters但是顺序乱掉一旦系统是高并发场景多个线程同时执行SQL时Preparing和Parameters正好是两个独立日志输出点线程间交错打印会让日志分析变得困难。这不是Bug而是多线程环境的天然特性。比较可靠的处理方式是引入traceId日志模式中加上%X{traceId}之类的MDC占位符这样同一个请求的所有SQL日志会有相同的traceId标签。再多线程日志也能通过traceId把所有相关SQL串起来看。在logback中配置MDC的示例pattern%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level [%X{traceId}] %logger{50} - %msg%n/pattern然后在你的过滤器中比如一个简单的OncePerRequestFilter放入traceIdMDC.put(traceId, UUID.randomUUID().toString().replace(-, ));这是个很实用的小技巧。否则你会面对一个极其难看的日志文件SQL完全乱序根本没法梳理某一个请求到底执行了哪些SQL。4.4 分页查询打印的SQL带了LIMIT但实际日志不完整MyBatis Plus的分页插件PaginationInnerInterceptor会在最终SQL执行前做二次处理把原SQL包装成COUNT查询SQL和实际的分页查询SQL。很多时候你看到的日志是 Preparing: SELECT COUNT(*) FROM user WHERE (age ?) Parameters: 20(Integer) Preparing: SELECT id,name,email,age FROM user WHERE (age ?) LIMIT ? Parameters: 20(Integer), 10(Long)注意这里LIMIT后面的?在Parameters中显示为10(Long)这已经算是完整信息了。但如果你用p6spy方式打印LIMIT后面的参数会直接写到SQL里比如LIMIT 10方便直接执行。两种方式都能接受看个人习惯。分页插件有个属性叫optimizeCountSql如果你发现COUNT查询与实际结果不一致可能要去检查这个配置项但和日志打印本身没有直接关系。还有一个我踩过的坑分页插件失效时日志依然只是打印原始SQL不加LIMIT。这种问题通常是因为没有配置MybatisPlusInterceptor或者配置了但顺序不对。看日志是最快的定位手段如果一个Page查询打印出来的SQL没有任何LIMIT那你就要先怀疑分页插件是否生效而不是怀疑日志配置有问题。4.5 生产环境打印大量日志导致磁盘暴涨曾经有个同事为了排查线上问题临时把生产环境的Mapper日志级别调整到了DEBUG结果一天生成了30GB日志文件把磁盘直接打满。这事提醒业务团队SQL日志的开启要有规范。生产中如果确需开启SQL日志以下几点建议非常值得注意只针对特定Mapper开启不要一股脑把整个包都设置为DEBUG只对出问题的那个Mapper设置即可。logback-spring.xml支持logger namecom.example.demo.mapper.UserMapper levelDEBUG/精确到类。设置独立的滚动策略和实时容量上限用maxHistory控制保留天数用SizeAndTimeBasedRollingPolicy按文件大小拆分比如单个日志文件达到200MB就滚动。通过配置中心动态切换比如使用Nacos Config logback的动态日志级别功能可以在不需要重启服务的情况下调整某个Mapper的日志级别排查完再调回INFO这样全程不影响大盘日志量。如果你所在公司有配置中心强烈建议用这个方案。使用慢SQL日志替代完整SQL日志MySQL的slow_query_log在生产中比MyBatis层打印所有SQL更温和它只记录超过long_query_time阈值的SQL天然过滤掉了大量正常请求。5. 日志格式的美化与进阶玩法5.1 配置输出更紧凑的SQL如果你用MyBatis自带的多行日志一条复杂的动态SQL可能长达几十行阅读起来非常费劲。我看到很多项目选择在SQL模板编写时就用script标签加空格换行来美化XML。但MyBatis Plus的日志输出源是BoundSql.getSql()它保持了你写的SQL原始格式包括换行和缩进。如果你的SQL模板本身比较整洁输出自然也会比较整洁。但很多XML里的SQL写了动态条件后拼接结果会带有大量多余空格。这时可以启动时配置一个ConfigurationCustomizer把mapUnderscoreToCamelCase等技术配置处理好但空格问题需要在SQL底层做处理。p6spy的customLogMessageFormat里可以写一个自定义的消息格式比如把多条空格压缩成单空格customLogMessageFormat%(sql)p6spy底层已经处理了多余换行和空格所以通常输出是单行紧凑的完整SQL阅读较为舒适。5.2 配合执行时间的输出定位慢SQL这里要提一个在MyBatis Plus自带日志中看不出来的信息SQL的真实执行耗时。MyBatis自带日志中的Preparing、Parameters、Total并不会包含每条SQL的执行时间所以定位慢SQL必须靠数据库层或者额外手段。p6spy默认会输出执行时间在spy.properties中可以通过%(executionTime)占位符将耗时写入日志。我通常会把logMessageFormat配置为customLogMessageFormat%(executionTime) ms | %(sql)然后结合告警规则对超过500毫秒的SQL单独拉出分析。这个阈值可以根据自己的业务实际情况调整高并发系统普遍定100200ms。另一种做法是在MyBatis拦截器中记录prepare到query结束的时间差覆盖所有执行路径。如果不想引入p6spy这个方法是最可控的。5.3 自定义MyBatis Plus配置类实现日志开关有一些项目希望通过一个配置项来控制是否打印SQL日志而不是来回改logback。这是一种面向更细粒度控制的做法可以自己写一个MybatisPlusConfig根据环境判断来动态设置log-impl。Configuration public class MybatisPlusConfig { Value(${app.sql-log-enabled:false}) private boolean sqlLogEnabled; Bean public ConfigurationCustomizer mybatisConfigurationCustomizer() { return configuration - { if (sqlLogEnabled) { configuration.setLogImpl(org.apache.ibatis.logging.stdout.StdOutImpl.class); } else { configuration.setLogImpl(org.apache.ibatis.logging.nologging.NoLoggingImpl.class); } }; } }这种方式的好处是可以配合Profile(dev)或者Spring Cloud Config的配置项实现环境隔离。但要注意一个细节configuration.setLogImpl设置的是一个Class对象MyBatis内部会为这个Log实现创建实例。如果项目里用了多个SqlSessionFactory每个都要重新配置一遍才行。6. 多数据源场景下SQL日志的配置细节6.1 多数据源为什么日志配置容易失效当项目需要配置多个数据源时比如读写分离、分库分表常规的做法是手动创建DataSource、SqlSessionFactory和SqlSessionTemplate。此时Spring Boot的AutoConfig可能被你自己定义的条件覆盖导致mybatis-plus.configuration.log-impl只对其中一个数据源生效。下面是一个多数据源配置场景中为什么会失效的例子如果你自己定义了两个SqlSessionFactory其中一个设置了MybatisConfiguration为log-implStdOutImpl另一个没有设置那么不经意的那个数据源的SQL就不会打印。排查这类问题的思路是确认每个SqlSessionFactory在构建时是否都调用了configuration.setLogImpl或者统一在一个Factory PostProcessor中处理。6.2 动态数据源路由的日志配置建议国内不少项目会使用DataSource注解方式实现动态数据源切换比如基于AbstractRoutingDataSource在这种情况下SQL日志的配置方式和主从库并没有本质区别因为最终还是落到某个SqlSessionFactory上。但如果你的路由在运行时动态切换了DataSource那么P6SpyDataSource这类代理连接在所有物理连接上统一生效反而是这类场景中更优的选择因为它可以在不改动多个SqlSessionFactory的前提下完成对所有数据源的SQL统一打印。在p6spy方案下多数据源接入只需确保每个DataSource最终通过P6SpyDataSource或者配置文件里的driver-class-name指定即可接入相对干净。7. 从日志到性能优化SQL日志实践的高级用法7.1 通过SQL日志验证索引是否生效如果线上某个接口响应慢你最先要看的不是代码逻辑而是实际执行的那条SQL是什么、执行计划是什么。多数情况下问题就出现在SQL没有走索引。把SQL日志开启后拿到完整SQL然后在Navicat里执行EXPLAIN观察type列和rows列。如果type是ALL全表扫描或者rows极大那就是索引设计有问题。此时再拿这条SQL去优化效率远远高于对着代码猜。这里给出一个我常用的排查链路慢接口确认 → 开启当前Mapper的SQL日志 → 拿到真实SQL和参数 → 数据库执行EXPLAIN→ 优化索引或改写SQL → 日志再次验证。我的一个项目曾经有个查询需要3秒钟打开SQL日志后发现它查的是一个三张表关联的视图视图在数据库中本身没有索引可用后来把这个视图拆成单表查询时间降到300毫秒。没有SQL日志这类问题定位会非常困难。7.2 结合MyBatis Plus的wrapper结构判断日志中的动态条件使用MyBatis Plus的LambdaQueryWrapper时代码中写了多个条件但某些条件下条件参数为null会自动忽略。这时候如果不看SQL日志根本看不出哪个条件被忽略了。比如LambdaQueryWrapperUser wrapper Wrappers.lambdaQuery(); wrapper.eq(User::getAge, age) .like(StringUtils.hasText(name), User::getName, name) .between(beginTime ! null, User::getCreateTime, beginTime, endTime);当name为空字符串、beginTime为null时日志里只会有第一个age条件。看日志能让你瞬间明白为什么查出来的数据和你预期的不一样。反之不看日志你会怀疑是不是框架有bug白白浪费几个小时的排查时间。所以我在团队里一直强调一个工作习惯涉及数据库问题的排查第一步永远是看SQL日志而不是读代码。这条习惯帮我避开了很多弯路。日志里的SQL和代码里的Wrapper写法有时会展现出巨大的思维差异而这种差异正是问题所在。7.3 自定义慢SQL拦截器与日志联动在拦截SQL日志的同时如果顺手把执行时间大于阈值的SQL记录到独立的慢日志文件对后期性能优化会有极大帮助。这样你可以按天归档慢SQL文件定期分析是不是有新增的全表扫描查询。下面给一个简单的思路基于MetaObject从StatementHandler中拿到BoundSql再结合PreparedStatement执行后的耗时将慢SQL输出到专门的日志通道long start System.currentTimeMillis(); Object result invocation.proceed(); long cost System.currentTimeMillis() - start; if (cost 500) { slowSqlLogger.warn(slow sql cost:{} ms, sql:{}, cost, sql); }这个拦截器可以和控制台SQL日志并存配置了独立的logger设置成WARN级别就只输出慢SQL不影响正常SQL。8. 一些被问烂了的零碎问题集中解答8.1 MyBatis Plus 3.5.x为什么有时候看不到Preparing日志3.5系列从某个版本开始对日志输出做了细节调整在某些执行路径上尤其是批量操作可能只打印一条Total而没有Preparing和Parameters。这是因为批量操作时MyBatis默认不会在每次执行时都把参数打印出来。解决办法是检查是否配置了executorTypeBATCH如果是批量模式建议临时切回到SIMPLE模式来观察SQL日志或者直接用p6spy。8.2 MyBatis Plus的SQL日志能直接体现JOIN查询吗可以。只要你的Mapper接口中定义的方法包含自定义SQL注解或XML形式MyBatis的日志一样会输出Preparing和ParametersJOIN查询的SQL和参数都完整可见。8.3 如何让SQL日志带上调用链路信息将MDC中的traceId集成到日志模式中然后让SQL日志也带上MDC上下文就能把一次前端请求的所有数据库操作串联起来。这在微服务排查中甜度极高。具体做法就是在日志框架的pattern中加入%X{traceId}然后通过你的网关或过滤器写入MDC。8.4 日志太多不想全部输出只想要慢SQL日志这种需求建议分两条路走如果数据库是MySQL直接用数据库层面的慢查询日志如果还想要MyBatis层面记录就参考上文自定义慢SQL拦截器。不要试图通过MyBatis Plus自带配置去实现因为它没有慢SQL这个维度。8.5 有没有办法在运行期动态打开SQL日志当然有主要思路是利用配置中心的配置动态刷新logback级别。比如使用Nacos/Apollo时把logger级别的配置放在可刷新的配置文件中然后在Spring Boot中配置一个LoggingSystem的动态监听。Spring Boot自带logging.level.*端点通过Actuator的/loggers接口也能动态调整POST /actuator/loggers/com.example.demo.mapper.UserMapper {configuredLevel:DEBUG}使用Actuator调整后立刻生效排查完再调回INFO即可。最后分享一段我个人的实操体会如果你问我在实际项目中最终长期采用的是哪种组合我的答案是本地开发完全靠logback的mapper包DEBUG级别输出配合IDEA控制台直接看Preparing和Parameters线上环境一般不全局开启SQL日志只开启某个特定Mapper或遇到性能问题时用p6spy临时打印带参数的真实SQL。这样既保证了排障效率又把日志量控制在了可接受范围内。还有一个小技巧值得分享SQL日志的调优场景永远比调试场景更值得花时间。把日志打开不是为了看那条SQL执行得对不对而是为了看出那条SQL到底是怎么被构建出来的。很多同事看日志只看结果不看拼接过程这是浪费了SQL日志最宝贵的价值。另外可以多扩展一步。如果你经常要分析系统的数据库操作逻辑可以考虑把日志里的SQL定期归档按小时或者按天存档用脚本做去重分析。比如找出当前业务中哪几条SQL被调用的次数最多、执行时间最长据此优化索引或者改写SQL。这一步做得好有时候比你在代码层面做的优化收益还要大。希望这篇围绕MyBatis Plus打印SQL日志的梳理对你有用。配置本身不复杂难的是理解背后的机制以及结合自己的场景选出合适的方案。配置出错没关系照着前面的排查思路一步步来总能找到问题所在。如果你的项目还有更多特殊的日志需求欢迎顺着这些思路去挖掘能折腾出来的灵活方案还有很多。
返回列表