Mybatis插件使用-统计sql执行时间

　　背景介绍：最近由于产品数据量较大，sql执行十分低效，正在做数据库优化，所以想在日志中看到每个sql执行的时间，以方便针对性的优化。

　　查找相关资料，了解到Mybatis有一款插件，是基于interceptor来实现的，可以在拦截器中来输出每个sql的执行时间，配置方便且简单，经过自测可用。

　　1、在dao的配置文件中，在sqlSessionFactory配置项里添加插件依赖：

    <bean id="sqlSessionFactory" class="org.mybatis.spring.SqlSessionFactoryBean">
        <property name="configLocation" value="classpath:mybatis-config.xml" />
        <property name="mapperLocations" value="classpath:/sqlmap/*Mapper.xml" />
        <property name="dataSource" ref="dataSource" />
        <property name="plugins">
            <array>
                <!-- 基于拦截器的实现，配置拦截器所在工程的全路径 -->
                <bean id="sqlStatementInterceptor" class="com.**.interceptor.SqlStatementInterceptor"/>
            </array>
        </property>
    </bean>

　　2、在工程com.**.interceptor包路径下添加SqlStatementInterceptor.java，具体代码如下：

/**
 * Mybatis SQL拦截器,记录每个sqlId对应的执行时间
 * 
 * @author yehaixiao
 * @date 2017-09-07
 */
@Intercepts(value = {
        @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 }),
        @Signature(type = Executor.class, method = "query", args = { MappedStatement.class, Object.class,
                RowBounds.class, ResultHandler.class, CacheKey.class, BoundSql.class }) })
public class SqlStatementInterceptor implements Interceptor {
    private static Logger logger = Logger.getLogger(SqlStatementInterceptor.class);

    @Override
    public Object intercept(Invocation invocation) {
        MappedStatement mappedStatement = (MappedStatement) invocation.getArgs()[0];
        // sqlId为mapper文件中定义的id，例如：com.**.dao.**Mapper.selectByPrimaryKey
        String sqlId = mappedStatement.getId();
        // 开始时间
        long start = System.currentTimeMillis();
        try {
            return invocation.proceed();
        } catch (Exception e) {
            logger.error(sqlId + "执行失败！", e);
            return null;
        } finally {
            long end = System.currentTimeMillis();
            long time = end - start;
            StringBuilder str = new StringBuilder();
            str.append(sqlId);
            str.append(": ");
            str.append("cost time ");
            str.append(time);
            str.append(" ms.");
            String sqlInfo = str.toString();
            logger.debug(sqlInfo);
        }
    }

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

    @Override
    public void setProperties(Properties arg0) {

    }
}

　　说明：自定义的拦截器实现了org.apache.ibatis.plugin.Interceptor，Interceptor中有三个方法：

public abstract interface Interceptor {
    public abstract Object intercept(Invocation paramInvocation) throws Throwable;

    public abstract Object plugin(Object paramObject);

    public abstract void setProperties(Properties paramProperties);
}

　　我们主要实现了intercept方法，入参是一个Invocation，Invocation的内部结构如下所示：　　

　　　　

　　第一个参数是长度为4的args数组，数组的第一个参数是一个MappedStatement，其实这个就是执行一个sql对应的对象，该对象中有个getId，获取到的结果就是mapper文件中sql定义的id，这样就很容易明白自定义的拦截器里intercept方法里第一句话含义。

　　直到现在，相关的配置、代码以及说明全都结束，在执行sql的时候，日志中可以看到如下输出：