Spring Boot集成MyBatis如何记录事务关联的查询日志

你当前仅开启了MyBatis Mapper层的SQL打印，Spring事务管理、JDBC连接绑定相关的日志级别被设置为WARN，且日志上下文没有事务唯一标识，因此无法将SQL语句和所属事务做关联。按以下步骤配置即可实现需求：

第一步：调整日志级别，开启事务核心日志 #

不需要删除原有logging.level.org.springframework=WARN配置，日志框架子包级别优先级高于父包，单独给事务相关模块开DEBUG级别即可，不会输出大量Spring框架无关日志。
在application.properties中新增以下配置：

# 保留原有Mapper层SQL日志配置
logging.level.com.example.demo.dao.UserMapper=DEBUG
logging.level.com.example.demo.dao.TransactionMapper=DEBUG

# 新增：开启Spring事务生命周期日志，可看到事务创建、参与、提交、回滚动作
logging.level.org.springframework.transaction=DEBUG
# 新增：开启JDBC连接与事务绑定日志，可看到连接和事务的对应关系
logging.level.org.springframework.jdbc.datasource=DEBUG
# 新增：Spring Boot 2.7默认使用HikariCP连接池，开启连接池日志可看到连接获取/归还与事务的关联
logging.level.com.zaxxer.hikari=DEBUG

配置完成后可看到类似Creating new transaction with name [业务方法名]、Participating in existing transaction、Committing JDBC transaction on Connection [HikariProxyConnection@xxxxxx]的日志，同一个事务会绑定唯一的Connection代理对象实例hash，后续MyBatis打印的SQL只要关联同一个Connection实例，就属于同一事务。

第二步：增加事务唯一标识（推荐，关联更直观） #

靠Connection hash关联不够直观，可以通过MDC给每个事务生成全局唯一短ID，直接打印在每行日志里，一眼就能区分SQL所属事务。

1. 编写事务ID绑定拦截器，事务开启时生成ID放入MDC，事务结束后自动清理：

import org.slf4j.MDC;
import org.springframework.stereotype.Component;
import org.springframework.transaction.support.TransactionSynchronizationAdapter;
import org.springframework.transaction.support.TransactionSynchronizationManager;
import org.springframework.web.servlet.HandlerInterceptor;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.util.UUID;

@Component
public class TransactionIdInterceptor implements HandlerInterceptor {
    private static final String TX_ID_MDC_KEY = "txId";

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
        if (TransactionSynchronizationManager.isSynchronizationActive()) {
            TransactionSynchronizationManager.registerSynchronization(new TransactionSynchronizationAdapter() {
                @Override
                public void afterBegin() {
                    // 生成8位短ID作为事务唯一标识
                    String txId = UUID.randomUUID().toString().replace("-", "").substring(0, 8);
                    MDC.put(TX_ID_MDC_KEY, txId);
                }

                @Override
                public void afterCompletion(int status) {
                    MDC.remove(TX_ID_MDC_KEY);
                }
            });
        }
        return true;
    }
}

2. 注册拦截器到Spring MVC配置中：

import org.springframework.context.annotation.Configuration;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;
import javax.annotation.Resource;

@Configuration
public class WebMvcConfig implements WebMvcConfigurer {
    @Resource
    private TransactionIdInterceptor transactionIdInterceptor;

    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(transactionIdInterceptor).addPathPatterns("/**");
    }
}

3. 修改日志输出格式，把事务ID打印到每行日志中，在application.properties新增配置：

# 日志格式中增加%X{txId} 输出MDC中存储的事务ID
logging.pattern.console=%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} [txId:%X{txId}] - %msg%n

配置完成后，无事务的SQL日志txId字段为空，同一事务下的所有日志（包括事务生命周期日志、SQL日志、连接池日志）都会携带相同的txId，直接通过ID即可归类同一事务的所有SQL。

第三步：PostgreSQL侧事务ID对齐（可选，用于数据库侧核对） #

如果需要和数据库层面的事务ID做一一对应，可以添加MyBatis拦截器，在事务内第一次执行SQL时查询PostgreSQL内部事务ID打印到日志中：

import org.apache.ibatis.executor.Executor;
import org.apache.ibatis.mapping.MappedStatement;
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.session.ResultHandler;
import org.apache.ibatis.session.RowBounds;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import org.springframework.transaction.support.TransactionSynchronizationManager;
import java.sql.Connection;
import java.sql.ResultSet;
import java.sql.Statement;

@Component
@Intercepts({
        @Signature(type = Executor.class, method = "update", args = {MappedStatement.class, Object.class}),
        @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class})
})
public class PgTxIdInterceptor implements Interceptor {
    private static final Logger log = LoggerFactory.getLogger(PgTxIdInterceptor.class);
    private static final ThreadLocal<Long> PG_TX_ID_CACHE = new ThreadLocal<>();

    @Override
    public Object intercept(Invocation invocation) throws Throwable {
        if (TransactionSynchronizationManager.isActualTransactionActive() && PG_TX_ID_CACHE.get() == null) {
            Executor executor = (Executor) invocation.getTarget();
            Connection conn = executor.getTransaction().getConnection();
            try (Statement stmt = conn.createStatement(); ResultSet rs = stmt.executeQuery("SELECT txid_current()")) {
                if (rs.next()) {
                    long pgTxId = rs.getLong(1);
                    PG_TX_ID_CACHE.set(pgTxId);
                    log.info("PostgreSQL internal transaction id: {}", pgTxId);
                }
            }
        }
        try {
            return invocation.proceed();
        } finally {
            if (!TransactionSynchronizationManager.isActualTransactionActive()) {
                PG_TX_ID_CACHE.remove();
            }
        }
    }
}

配置生效后的日志示例 #

2024-05-20 15:22:31.123 [http-nio-8080-exec-3] DEBUG o.s.t.i.TransactionInterceptor [txId:f2d7e9a1] - Getting transaction for [com.example.demo.service.OrderService.createOrder]
2024-05-20 15:22:31.126 [http-nio-8080-exec-3] DEBUG o.s.j.d.DataSourceTransactionManager [txId:f2d7e9a1] - Creating new transaction with name [com.example.demo.service.OrderService.createOrder]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2024-05-20 15:22:31.201 [http-nio-8080-exec-3] INFO  c.e.d.config.PgTxIdInterceptor [txId:f2d7e9a1] - PostgreSQL internal transaction id: 927416
2024-05-20 15:22:31.208 [http-nio-8080-exec-3] DEBUG c.e.d.dao.UserMapper.selectById [txId:f2d7e9a1] - ==>  Preparing: SELECT id,name,balance FROM user WHERE id = ?
2024-05-20 15:22:31.210 [http-nio-8080-exec-3] DEBUG c.e.d.dao.UserMapper.selectById [txId:f2d7e9a1] - ==> Parameters: 1001(Long)
2024-05-20 15:22:31.223 [http-nio-8080-exec-3] DEBUG c.e.d.dao.OrderMapper.insert [txId:f2d7e9a1] - ==>  Preparing: INSERT INTO order (user_id,amount,create_time) VALUES (?,?,?)
2024-05-20 15:22:31.225 [http-nio-8080-exec-3] DEBUG c.e.d.dao.OrderMapper.insert [txId:f2d7e9a1] - ==> Parameters: 1001(Long), 99.00(BigDecimal), 2024-05-20 15:22:31(Timestamp)
2024-05-20 15:22:31.241 [http-nio-8080-exec-3] DEBUG c.e.d.dao.UserMapper.updateBalance [txId:f2d7e9a1] - ==>  Preparing: UPDATE user SET balance = balance - ? WHERE id = ?
2024-05-20 15:22:31.242 [http-nio-8080-exec-3] DEBUG c.e.d.dao.UserMapper.updateBalance [txId:f2d7e9a1] - ==> Parameters: 99.00(BigDecimal), 1001(Long)
2024-05-20 15:22:31.257 [http-nio-8080-exec-3] DEBUG o.s.j.d.DataSourceTransactionManager [txId:f2d7e9a1] - Initiating transaction commit
2024-05-20 15:22:31.258 [http-nio-8080-exec-3] DEBUG o.s.j.d.DataSourceTransactionManager [txId:f2d7e9a1] - Committing JDBC transaction on Connection [HikariProxyConnection@1827364 wrapping org.postgresql.jdbc.PgConnection@7a2d9f3]

所有携带相同txId:f2d7e9a1的SQL都属于同一事务，可直接归类。

内容的提问来源于stack exchange，提问作者Majid Abdolhosseini