使用MybatisPlus實現sql日志打印優化

背景：

在排查無憂行后臺服務日志時，一個請求可能會包含多個執行的sql，經常會遇到SQL語句與對應參數不連續顯示，或者參數較多需要逐個匹配的情況。這種情況下，如果需要還原完整SQL語句就會比較耗時。因此，我希望能優化這一流程。

正文：

在平時排查sql執行情況時，對于sql查詢參數比較多或者多個sql在同一個請求下執行的時候會比較麻煩，需要查看每個參數的值一一對應檢查是否有異常，有時候還需要將查詢sql的問號還原去庫里面查詢結果，就類似下面的日志：
在這里插入圖片描述

一個一個參數還原比較麻煩，因此針對這種問題，我找到了一個解決辦法，重寫MybatisPlus的InnerInterceptor，將sql日志重新組裝，那么在查看sql日志時候就可以直接查看賦值好參數的sql了，將上面截圖的sql整合之后可以轉化為下面的sql：
在這里插入圖片描述

具體的思路以及實現方案，以無憂行項目為例

實現思路，利用mybatisplus提供的接口InnerInterceptor，重寫sql日志，并將重寫之后的類注入到sqlSessionFactory中，在執行sql之前捕獲到并打印。
解釋一下InnerInterceptor類：InnerInterceptor 是 MyBatis-Plus 框架中的一個核心攔截器接口，它是 MyBatis 攔截器機制的擴展，用于在 SQL 執行過程中進行攔截和增強。
InnerInterceptor工作原理：InnerInterceptor 通過 MyBatis 的插件機制工作，在以下時機進行攔截：

- beforeQuery：查詢操作執行前
- beforeUpdate：更新操作執行前
- beforePrepare：SQL 準備階段

針對查詢sql執行的sql重整，使用的是beforeQuery，針對更新sql執行的重整，使用的是beforeUpdate，以下是具體實現：

1.首先，添加依賴，

maven依賴：

<dependency><groupId>com.baomidou</groupId><artifactId>mybatis-plus-boot-starter</artifactId><version>3.4.0</version>
</dependency>

或者gradle依賴：

compile("com.baomidou:mybatis-plus-generator:3.4.0")

2.重寫InnerInterceptor

package com.cmi.jego.micro.flight.admin.service.config;import com.baomidou.mybatisplus.extension.plugins.inner.InnerInterceptor;
import lombok.extern.slf4j.Slf4j;
import org.apache.commons.collections4.CollectionUtils;
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.reflection.MetaObject;
import org.apache.ibatis.session.Configuration;
import org.apache.ibatis.session.ResultHandler;
import org.apache.ibatis.session.RowBounds;
import org.apache.ibatis.type.TypeHandlerRegistry;import java.sql.SQLException;
import java.text.DateFormat;
import java.util.Date;
import java.util.List;
import java.util.Locale;
import java.util.regex.Matcher;/*** sql日志重寫** @author zhouxy* @date 2025年05月08日 11:27*/
@Slf4j
@org.springframework.context.annotation.Configuration
public class MybatisPlusLogRewrite implements InnerInterceptor {@Overridepublic void beforeQuery(Executor executor, MappedStatement ms, Object parameter, RowBounds rowBounds, ResultHandler resultHandler, BoundSql boundSql) throws SQLException {log.info("beforeQuery");logInfo(boundSql, ms, parameter);}@Overridepublic void beforeUpdate(Executor executor, MappedStatement ms, Object parameter) throws SQLException {log.info("beforeUpdate");BoundSql boundSql = ms.getBoundSql(parameter);logInfo(boundSql, ms, parameter);}private static void logInfo(BoundSql boundSql, MappedStatement ms, Object parameter) {try {// 獲取到節點的id,即sql語句的idString sqlId = ms.getId();// 獲取節點的配置Configuration configuration = ms.getConfiguration();// 獲取到最終的sql語句String sql = getSql(configuration, boundSql, sqlId);log.info("完整的sql:{}", sql);} catch (Exception e) {log.error("異常:{}", e.getLocalizedMessage(), e);}}// 封裝了一下sql語句，使得結果返回完整xml路徑下的sql語句節點id + sql語句public static String getSql(Configuration configuration, BoundSql boundSql, String sqlId) {return sqlId + ":" + showSql(configuration, boundSql);}// 進行？的替換public static String showSql(Configuration configuration, BoundSql boundSql) {// 獲取參數Object parameterObject = boundSql.getParameterObject();List<ParameterMapping> parameterMappings = boundSql.getParameterMappings();
//        log.info("boundSql:{}",boundSql.getSql());// sql語句中多個空格都用一個空格代替String sql = boundSql.getSql().replaceAll("[\\s]+", " ");if (CollectionUtils.isNotEmpty(parameterMappings) && parameterObject != null) {// 獲取類型處理器注冊器，類型處理器的功能是進行java類型和數據庫類型的轉換TypeHandlerRegistry typeHandlerRegistry = configuration.getTypeHandlerRegistry();// 如果根據parameterObject.getClass(）可以找到對應的類型，則替換if (typeHandlerRegistry.hasTypeHandler(parameterObject.getClass())) {sql = sql.replaceFirst("\\?",Matcher.quoteReplacement(getParameterValue(parameterObject)));} else {// MetaObject主要是封裝了originalObject對象，提供了get和set的方法用于獲取和設置originalObject的屬性值,主要支持對JavaBean、Collection、Map三種類型對象的操作MetaObject metaObject = configuration.newMetaObject(parameterObject);for (ParameterMapping parameterMapping : parameterMappings) {String propertyName = parameterMapping.getProperty();if (metaObject.hasGetter(propertyName)) {Object obj = metaObject.getValue(propertyName);sql = sql.replaceFirst("\\?",Matcher.quoteReplacement(getParameterValue(obj)));} else if (boundSql.hasAdditionalParameter(propertyName)) {// 該分支是動態sqlObject obj = boundSql.getAdditionalParameter(propertyName);sql = sql.replaceFirst("\\?",Matcher.quoteReplacement(getParameterValue(obj)));} else {// 打印出缺失，提醒該參數缺失并防止錯位sql = sql.replaceFirst("\\?", "缺失");}}}}return sql;}// 如果參數是String，則添加單引號， 如果是日期，則轉換為時間格式器并加單引號； 對參數是null和不是null的情況作了處理private static String getParameterValue(Object obj) {String value;if (obj instanceof String) {value = "'" + obj.toString() + "'";} else if (obj instanceof Date) {DateFormat formatter = DateFormat.getDateTimeInstance(DateFormat.DEFAULT,DateFormat.DEFAULT, Locale.CHINA);value = "'" + formatter.format(new Date()) + "'";} else {if (obj != null) {value = obj.toString();} else {value = "";}}return value;}
}

3.將當前的重寫類MybatisPlusLogRewrite注入到sqlSessionFactory中。

package com.cmi.jego.micro.flight.admin.service.config;import com.baomidou.mybatisplus.extension.plugins.MybatisPlusInterceptor;
import org.apache.ibatis.session.SqlSessionFactory;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.context.annotation.Configuration;import javax.annotation.PostConstruct;
import java.util.List;/*** @author zhouxy* @date 2025年05月09日 15:58*/
@Configuration
public class MyBatisPlusConfig {@Autowiredprivate List<SqlSessionFactory> sqlSessionFactoryList;@Autowiredprivate MybatisPlusLogRewrite myInnerInterceptor;/*** 添加Mybatis攔截器** @author zhouxy* @date 2025/5/15 16:29*/@PostConstructpublic void addMybatisInterceptor() {for (SqlSessionFactory sqlSessionFactory : sqlSessionFactoryList) {org.apache.ibatis.session.Configuration configuration = sqlSessionFactory.getConfiguration();//將sql攔截器添加到MybatisPlusInterceptor攔截器鏈MybatisPlusInterceptor mybatisPlusInterceptor = new MybatisPlusInterceptor();mybatisPlusInterceptor.addInnerInterceptor(myInnerInterceptor);configuration.addInterceptor(mybatisPlusInterceptor);}}
}

關閉其他sql打印日志，執行查詢sql，只打印當前重寫之后的sql日志如下：

2025-05-14 18:03:01.353  INFO 34718 --- [           main] c.c.j.m.f.a.service.handler.LogHandler   : function:[OrderRefundServiceImpl.queryOrderListStatusCount], request: {"lang":"zh_CN","pageNum":1,"pageSize":10}
2025-05-14 18:03:01.385  INFO 34718 --- [           main] c.c.j.m.f.a.s.c.MybatisPlusLogRewrite    : beforeQuery
2025-05-14 18:03:01.387  INFO 34718 --- [           main] c.c.j.m.f.a.s.c.MybatisPlusLogRewrite    : 完整的sql:com.cmi.jego.micro.flight.admin.service.mapper.jegotrip.TicketRefundMapper.queryListStatusCount:select distinct(tr.id) as refundId, tr.status from ticket_refund tr left join ticket_order td on tr.order_id = td.order_id left join ticket_passenger tp on tr.order_id = tp.order_id left join ticket_order_detail tod on tr.order_id = tod.order_id WHERE ( td.search_channel in ( 'hbgj-api-domestic-custom' ) or (td.order_source is null and td.search_channel is null) or td.order_source = '0' )
2025-05-14 18:03:01.395  WARN 34718 --- [           main] c.a.druid.pool.DruidAbstractDataSource   : discard long time none received connection. , jdbcUrl : jdbc:mysql://localhost:3306/ticket_jegotrip?useUnicode=true&characterEncoding=UTF-8&zeroDateTimeBehavior=convertToNull&serverTimezone=GMT%2B8, version : 1.2.5, lastPacketReceivedIdleMillis : 263261
2025-05-14 18:03:01.395  WARN 34718 --- [           main] c.a.druid.pool.DruidAbstractDataSource   : discard long time none received connection. , jdbcUrl : jdbc:mysql://localhost:3306/ticket_jegotrip?useUnicode=true&characterEncoding=UTF-8&zeroDateTimeBehavior=convertToNull&serverTimezone=GMT%2B8, version : 1.2.5, lastPacketReceivedIdleMillis : 263912
2025-05-14 18:03:01.396  WARN 34718 --- [           main] c.a.druid.pool.DruidAbstractDataSource   : discard long time none received connection. , jdbcUrl : jdbc:mysql://localhost:3306/ticket_jegotrip?useUnicode=true&characterEncoding=UTF-8&zeroDateTimeBehavior=convertToNull&serverTimezone=GMT%2B8, version : 1.2.5, lastPacketReceivedIdleMillis : 263933
2025-05-14 18:03:01.396  WARN 34718 --- [           main] c.a.druid.pool.DruidAbstractDataSource   : discard long time none received connection. , jdbcUrl : jdbc:mysql://localhost:3306/ticket_jegotrip?useUnicode=true&characterEncoding=UTF-8&zeroDateTimeBehavior=convertToNull&serverTimezone=GMT%2B8, version : 1.2.5, lastPacketReceivedIdleMillis : 263958
2025-05-14 18:03:01.396  WARN 34718 --- [           main] c.a.druid.pool.DruidAbstractDataSource   : discard long time none received connection. , jdbcUrl : jdbc:mysql://localhost:3306/ticket_jegotrip?useUnicode=true&characterEncoding=UTF-8&zeroDateTimeBehavior=convertToNull&serverTimezone=GMT%2B8, version : 1.2.5, lastPacketReceivedIdleMillis : 263986
2025-05-14 18:03:01.851  INFO 34718 --- [           main] c.c.j.m.f.a.s.c.MybatisPlusLogRewrite    : beforeQuery
2025-05-14 18:03:01.851  INFO 34718 --- [           main] c.c.j.m.f.a.s.c.MybatisPlusLogRewrite    : 完整的sql:com.cmi.jego.micro.flight.admin.service.mapper.jegotrip.TicketRefundMoneyMapper.queryFailedByRefundIds:SELECT id , order_id, user_id, refund_id, pay_order_id, supplier_order_id, type, price, refund_price, status, refund_time, limit_time, refund_no, create_time, update_time, remark FROM ticket_refund_money WHERE refund_id IN ( 1295 , 1296 , 1423 , 1424 ) AND status = 4
2025-05-14 18:03:01.871  INFO 34718 --- [           main] c.c.j.m.f.a.service.handler.LogHandler   : class:[OrderRefundServiceImpl.queryOrderListStatusCount] response: {"bizCode":0,"bizMsg":"SUCCESS","data":{"statusCounts":[{"count":1,"status":-1,"statusDesc":"已取消"},{"count":2,"status":3,"statusDesc":"已退票退款"},{"count":1,"status":4,"statusDesc":"退票異常"}]},"rpcCode":0,"rpcMsg":"SUCCESS"}, cost: 521,
2025-05-14 18:03:01.876  INFO 34718 --- [           main] c.c.j.m.f.a.s.s.OrderRefundServiceTest   : {"bizCode":0,"bizMsg":"SUCCESS","data":{"statusCounts":[{"count":1,"status":-1,"statusDesc":"已取消"},{"count":2,"status":3,"statusDesc":"已退票退款"},{"count":1,"status":4,"statusDesc":"退票異常"}]},"rpcCode":0,"rpcMsg":"SUCCESS"}

性能評估方面

重寫InnerInterceptor類其實是在SqlSessionFactory中添加了攔截器，那么性能如何呢？下面是我這邊實際測試的時長對比

不添加sql重寫：

在這里插入圖片描述

添加sql重寫：

在這里插入圖片描述

根據測試時間可以看出，加了sql重寫會比未加的時候的時間長了11ms。
因為涉及到攔截以及反射，性能比不加的時候會稍微耗時一些，
如果是訪問量不高的情況下，用戶對于加沒加sql重寫的主觀感應時長其實差不多，因此這種sql重寫方案適合后臺訪問并發量不高的情況使用。
如果是并發量較高且比較注重性能的情況下，不建議加。