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

·  阅读 212

系列文章目录


@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 拓展-定制日志组件

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

分类:
后端
标签:
收藏成功!
已添加到「」, 点击更改