MyBatis拦截器应用 — 打印Sql执行时间与检测异常Sql

背景

在Mybatis项目中，代码测试的时候，想要知道每一个Sql在代码中的执行时间以及返回结果来判断Sql编写的是否有问题，一开始只是在自己怀疑有问题的Sql的mapper方法前后获取时间进行打印，但是，当项目里面的Sql很多的时候，这种方法显然不能够一劳永逸，那么有没有一种方法可以自动获取到每一个mapper中的每一个Sql语句的执行时间和执行结果呢？

解决方案

刚开时的时候想到了Springboot中的AOP功能，后来发现SpringBoot中的AOP切面功能切不到mapper中的方法，原因是mapper是接口而不是具体的实现类，因此使用AOP切不到mapper的具体实现，智能找另一种方法。

网上查找到另一种实现方式，也就是使用Mybatis的拦截器，拦截器的使用比较简单，继承自Interceptor类，然后在**@Intercepts**注解里面添加要拦截的Mybatis方法即可。通过拦截器可以很方便获取到执行方法，它的使用方式和SpringBoot的AOP切面操作有点类似，但是看它实现应该是使用的函数回调而不是像AOP那样是使用动态代理来实现的。具体原理不赘述，网上有很多这样的文章讲解。

下面通过拦截器来实现一个异常SQL检测的功能

代码实现

import lombok.extern.slf4j.Slf4j;
import org.apache.ibatis.executor.Executor;
import org.apache.ibatis.executor.statement.StatementHandler;
import org.apache.ibatis.mapping.MappedStatement;
import org.apache.ibatis.plugin.*;
import org.apache.ibatis.session.ResultHandler;
import org.apache.ibatis.session.RowBounds;
import org.springframework.context.annotation.Configuration;
import org.springframework.stereotype.Component;

import java.sql.Statement;
import java.util.List;

/**
 * Sql执行时间记录拦截器，此拦截器会将异常的Sql进行打印，包过执行超时的，返回结果异常多的Sql
 *
 * @author wangp
 */
@Intercepts({
        @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}),
        @Signature(type = Executor.class, method = "update", args = {MappedStatement.class, Object.class})
})

@Component
@Configuration
@Slf4j
public class SqlCheckInterceptor implements Interceptor {

    private static final boolean DEBUG = true;
    /**
     * 超时警告时间临界值，超过这个时间的Sql将会被打印警告
     */
    private static final int LIMIT_QUERY_TIME = 2000;
    /**
     * 返回长度警告临界值，超过这个长度的Sql将会被打印警告
     */
    private static final int MAX_LENGTH = 5000;

    @Override
    public Object intercept(Invocation invocation) throws Throwable {
        if (!DEBUG) {
            return invocation.proceed();
        }

        long startTime = System.currentTimeMillis();
        String sql = null;
        try {
            Object[] args = invocation.getArgs();
            if (args != null && args.length > 0 && args[0] instanceof MappedStatement) {
            	// 定位到是哪一个mapper的哪一个函数
                sql = ((MappedStatement) args[0]).getId();
            }
            Object proceed = invocation.proceed();
            if (proceed instanceof List) {
                if (((List<?>) proceed).size() > MAX_LENGTH) {
                    log.warn(">> [SQL WARN:数据量过多 ({})条] -> [{}]", ((List<?>) proceed).size(), sql);
                }
            }
            return proceed;
        } finally {
            long sqlCost = System.currentTimeMillis() - startTime;
            if (sqlCost > LIMIT_QUERY_TIME) {
                log.warn(">> [SQL WARN:执行超过时限({})ms] -> [{}]", sqlCost, sql);
            }
        }
    }

    @Override
    public Object plugin(Object target) {
        return Plugin.wrap(target, this);
    }

    @Override
    public void setProperties(java.util.Properties properties) {

    }

}

代码简述

上面首先我们通过注解拦截了Executor的两个方法query与update，虽然这里只拦截了两个方法，但是细心地伙伴可以发现Executor里面只会有这两个和sql执行有关的方法，原因估计就在于update,insert,delete这三种头属于update范畴，因此这里就已经把增删改查数据库的四种操作已经涵盖了，后面的args是每个方法所需要的参数，这个可以通过Executor的源码看到。

值得注意的是我们拦截的Executor的方法的第一个参数都是MappedStatement，这个参数封装了我们定义在mapper中的sql信息，通过这个参数我们就可以定位到这个拦截器拦截的究竟是那个mapper中的哪一个函数。获取mapper函数的方式也很简单，获取第一个参数，然后调用它的getId方法即可。

在上面的逻辑中，首先定位到具体的mapper函数，然后获取执行时间，这里做了两个限制，1. 超过2S的sql会被警告 2. 返回数据个数超过5000条的Sql会被警告

注册拦截器

把写完的拦截器注册进mybatis中即可

  /**
     * 根据数据源创建SqlSessionFactory
     */
    @Bean
    public SqlSessionFactory sqlSessionFactory(DynamicDataSource ds) throws Exception {
        PathMatchingResourcePatternResolver resolver = new PathMatchingResourcePatternResolver();
        SqlSessionFactoryBean fb = new SqlSessionFactoryBean();
        // 指定数据源(这个必须有，否则报错)
        fb.setDataSource(ds);
        // 指定基包
        fb.setTypeAliasesPackage("com.example.entity");
        fb.setMapperLocations(resolver.getResources("classpath:mapper/**/*.xml"));
        fb.setPlugins(new SqlCheckInterceptor());
        return fb.getObject();
    }

效果

这样在我们代码运行的时候，会自动打印出来可能存在问题的SQL，很方便我们进行问题的排查，例如下面是我的日志的输出，实际工作中感觉也挺实用的，能快速排查sql问题。

>> [SQL WARN:执行超过时限(3463)ms] -> [com.example.mapper.TestMapper.findMaxAcquisitionTimeBy]
>> [SQL WARN:数据量过多 (4322)条] -> [{com.example.mapper.TestMapper.queryAllData}]

通过日志可以很方便观察到可能是哪一个sql出现了问题，然后就进行判断这个sql有没有优化的必要，从而排除项目中因为sql问题而导致的卡顿或者执行时间过长的问题。