系列文章目录

@TOC

前言

在日常开发当中，我们经常需要通过SQL语句和执行耗时来定位问题。但mybatis框架是没有直接提供这种能力，只提供了非完整（即带” ？“ 占位符）语句的打印，不是很方便。

那我们有什么方法实现目标呢？

1、数据库慢查询日志优点：实现简单缺点：和业务日志有断层，且不一定有机器权限

2、p6spy、log4jdbc、 jdbcdslog-exp 等组件优点：无需编码，只需配置缺点：改变了原有的配置习惯，不通用

3、更换druid连接池优点：自带监控功能缺点：公司不推荐、已经集成号称速度最快的hikariCP

4、mybatis拦截器优点：通用、灵活性高、可对接日志和告警系统缺点：需自行编码、要考虑性能

5、APM工具优点：统一链路跟踪缺点：接入和维护成本略高

综上所述，这里采用方式4，拦截器方式。

一、本文要点

接前文，我们已经在项目里集成了mybatis和hikariCP。本文将介绍如何通过编写mybatis拦截器的方式，打印完整的SQL语句和执行时间。系列文章完整目录

springboot 打印完整SQL语句和执行时间
mybatis 打印完整SQL语句和耗时
hikari 打印完整SQL语句和耗时
mybatis 自定义拦截器
Executor、StatementHandler

二、开发环境

jdk 1.8
maven 3.6.2
springboot 2.4.3
mybatis 1.3.0
hikariCP
idea 2020

三、创建项目

1、使用早期文章快速创建项目。

《搭建大型分布式服务（五）Springboot整合mybatis》《搭建大型分布式服务（六）SpringBoot整合数据库连接池hikari》《搭建大型分布式服务（十八）Maven自定义项目脚手架》

2、创建Book项目

mvn archetype:generate  -DgroupId="com.mmc.lesson" -DartifactId="book" -Dversion=1.0-SNAPSHOT -Dpackage="com.mmc.lesson" -DarchetypeArtifactId=member-archetype  -DarchetypeGroupId=com.mmc.lesson -DarchetypeVersion=1.0.0-SNAPSHOT -B

四、修改项目

1、修改SqlLogConfig.java，用来控制是否打印语句。

@Component("sqlLogConfig")
@ConfigurationProperties(prefix = "sqllog")
@Data
public class SqlLogConfig {

    /**
     * 是否开启记录SQL日志，默认为false.
     */
    private boolean enabled;

    /**
     * 记录执行时间超过多少毫秒的语句，默认0，记录所有语句.
     */
    private int minCost;
    
}

2、修改MemberDataSourceConfiguration.java，添加mybatis拦截器到SqlSessionFactory。

    @Resource
    private SqlLogConfig sqlLogConfig;

    @Bean(name = "hikariSqlSessionFactory")
    public SqlSessionFactory setSqlSessionFactory(@Qualifier("hikariDataSource") DataSource dataSource)
            throws Exception {
        SqlSessionFactoryBean bean = new SqlSessionFactoryBean();
        bean.setDataSource(dataSource);
        // 添加拦截器
        bean.setPlugins(new Interceptor[]{new SqlStatementInterceptor(sqlLogConfig),
                new SqlExecuteTimeCountInterceptor(sqlLogConfig)});
        bean.setMapperLocations(
                new PathMatchingResourcePatternResolver().getResources("classpath:mysqlMappers/*.xml"));
        bean.setVfs(SpringBootVFS.class);
        return bean.getObject();
    }

3、编写SqlStatementInterceptor.java，因为我们用的连接池是hikariCP，到HikariProxyPreparedStatement完成阶段就是完整的sql语句了，由于mybatis的Executor和StatementHandler是顺序执行的，所以我们可以用基于ThreadLocal的SqlHolder.java来存储，这里我们只拦截select语句。

@Intercepts({
        @Signature(type = StatementHandler.class, method = "query", args = {Statement.class, ResultHandler.class})})
public class SqlStatementInterceptor implements Interceptor {

    private SqlLogConfig sqlLogConfig;

    public SqlStatementInterceptor(SqlLogConfig sqlLogConfig) {
        this.sqlLogConfig = sqlLogConfig;
    }

    @Override
    public Object intercept(Invocation invocation) throws Throwable {

        try {
            return invocation.proceed();
        } finally {

            // 是否开启记录sql
            if (sqlLogConfig.isEnabled()) {

                HikariProxyPreparedStatement statement;

                // 获取方法参数
                Object firstArg = invocation.getArgs()[0];
                if (Proxy.isProxyClass(firstArg.getClass())) {
                    statement = (HikariProxyPreparedStatement) SystemMetaObject.forObject(firstArg)
                            .getValue("h.statement");
                } else {
                    statement = (HikariProxyPreparedStatement) firstArg;
                }

                // 获取sql语句
                String originalSql = beautifySql(statement.toString());
                // 设置当前线程执行的sql语句
                SqlHolder.setSql(originalSql);
            }
        }
    }


    @Override
    public Object plugin(Object target) {

        if (target instanceof StatementHandler) {
            return Plugin.wrap(target, this);
        }
        return target;
    }

    @Override
    public void setProperties(Properties properties) {

    }

    private String beautifySql(String sql) {

        int index = sql.toUpperCase().indexOf("SELECT");
        if (index > -1) {
            return sql.substring(index).replaceAll("\\s+", " ");
        }
        return sql;
    }
}

public class SqlHolder {

    private static ThreadLocal<String> CONTEXT = new ThreadLocal<>();

    public static void setSql(String sql) {

        CONTEXT.set(sql);
    }

    public static String getSql() {
        return CONTEXT.get();
    }
}

4、编写SqlExecuteTimeCountInterceptor.java，用来计算SQL的执行时间，并从SqlHolder中取出存储的语句。

@Intercepts({@Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class,
        RowBounds.class, ResultHandler.class,
        CacheKey.class, BoundSql.class}),
        @Signature(type = Executor.class, method = "query", args = {MappedStatement.class, Object.class,
                RowBounds.class, ResultHandler.class})})
public class SqlExecuteTimeCountInterceptor implements Interceptor {

    private static Logger log = LoggerFactory.getLogger("SQL_LOG");

    private SqlLogConfig sqlLogConfig;

    public SqlExecuteTimeCountInterceptor(SqlLogConfig sqlLogConfig) {
        this.sqlLogConfig = sqlLogConfig;
    }

    @Override
    public Object intercept(Invocation invocation) throws Throwable {

        long startTime = System.currentTimeMillis();

        try {
            return invocation.proceed();
        } finally {

            // 是否开启记录sql
            if (sqlLogConfig.isEnabled()) {

                long endTime = System.currentTimeMillis();
                long timeCount = endTime - startTime;

                if (timeCount >= sqlLogConfig.getMinCost()) {
                    String originalSql = SqlHolder.getSql();
                    log.info("执行SQL: [ {} ]执行耗时ms: {} ", originalSql, timeCount);
                }
            }
        }
    }
    @Override
    public Object plugin(Object target) {

        if (target instanceof Executor) {
            return Plugin.wrap(target, this);
        }
        return target;
    }
    @Override
    public void setProperties(Properties properties) {

    }
}

5、修改logback，单独打印SQL语句。

    <!-- 时间滚动输出 SQL 日志 -->
    <appender name="SQL_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!-- 正在记录的日志文件的路径及文件名 -->
        <file>${log.path}/sql.log</file>
        <!--日志文件输出格式-->
        <encoder>
            <pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%thread] [%level] [%logger{50}:%L] - %msg%n</pattern>
            <charset>UTF-8</charset> <!-- 此处设置字符集 -->
        </encoder>
        <!-- 日志记录器的滚动策略，按日期，按大小记录 -->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${log.path}/sql/sql-%d{yyyy-MM-dd}.%i.gz</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>1GB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <!--日志文件保留天数-->
            <maxHistory>7</maxHistory>
            <totalSizeCap>7GB</totalSizeCap>
            <cleanHistoryOnStart>true</cleanHistoryOnStart>
        </rollingPolicy>
    </appender>

    <!-- SQL日志 -->
    <logger name="SQL_LOG" level="INFO" additivity="false">
        <appender-ref ref="SQL_FILE"/>
    </logger>

6、修改application-dev.properties 增加配置，其它环境同理。

#################### sqllog ####################
# 记录sql
sqllog.enabled=true
# 耗时下限ms
sqllog.min-cost=1

五、测试一下

1、修改并运行单元测试

    @RepeatedTest(5) // 重复5次，可以看到只打印一次 load data from db
    void get() {

        TblMemberInfo book = new TblMemberInfo();
        book.setUid(8888L);

        TblMemberInfo ret = bookService.get(book);
        assertThat(ret).isNotNull();
        log.info("--------------------------------------------------");
        log.info(ret.getUname());
        assertThat(ret.getUname()).isEqualTo("zhangsan");

    }

2、测试通过。

[2021-07-08 15:32:27.321] [main] [INFO] [SQL_LOG:69] - 执行SQL: [ select uid, uname, usex, ubirth, utel, uaddr, createTime, updateTime, state, delFlag , uphoto from Tbl_MemberInfo where uid = 8888 ]执行耗时ms: 74

六、小结

至此，我们就简单实现了自定义mybatis拦截器功能啦。线上环境可以通过sqllog.min-cost控制耗时多长时间才打印语句哦，小伙伴们可以发挥自己的动手能力，接入告警或者封装成组件。下一篇《搭建大型分布式服务（二十二）Springboot 拓展-定制日志组件》

加我加群一起交流学习！更多干货下载和大厂内推等着你

搭建大型分布式服务（二十一）Mybatis 如何打印SQL语句和执行时间？