【DB系列】 SQL执行日志打印的几种方式

SpringBootDB系列Mybatis
|
文章目录
  1. I. 项目配置
    1. 1. 依赖
    2. 2. 配置
  2. II. 实例
    1. 1. mybatis默认配置
    2. 2. Druid日志输出
    3. 3. 基于Mybatis的Interceptor实现方案
    4. 3. 小结
  3. III. 不能错过的源码和相关知识点
    1. 0. 项目
    2. 1. 微信公众号: 一灰灰Blog

sql日志打印，再我们日常排查问题时，某些时候帮助可以说是非常大的，那么一般的Spring项目中，可以怎么打印执行的sql日志呢？

本文将介绍三种sql日志打印的方式：

  1. Druid打印sql日志
  2. Mybatis自带的日志输出
  3. 基于拦截器实现sql日志输出

I. 项目配置

1. 依赖

首先搭建一个标准的SpringBoot项目工程，相关版本以及依赖如下

本项目借助SpringBoot 2.2.1.RELEASE + maven 3.5.3 + IDEA进行开发

添加web支持，用于配置刷新演示

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
<dependencies>
    <dependency>
        <groupId>org.mybatis.spring.boot</groupId>
        <artifactId>mybatis-spring-boot-starter</artifactId>
        <version>2.2.0</version>
    </dependency>
    <dependency>
        <groupId>mysql</groupId>
        <artifactId>mysql-connector-java</artifactId>
    </dependency>


    <!-- https://mvnrepository.com/artifact/com.alibaba/druid-spring-boot-starter -->
    <dependency>
        <groupId>com.alibaba</groupId>
        <artifactId>druid-spring-boot-starter</artifactId>
        <version>1.2.13</version>
    </dependency>
</dependencies>

2. 配置

接下来配置一下db的相关配置 application.yml

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
spring:
  datasource:
    druid:
      url: jdbc:mysql://localhost:3306/story?characterEncoding=UTF-8&zeroDateTimeBehavior=convertToNull&autoReconnect=true&generateSimpleParameterMetadata=true&failOverReadOnly=false&connectTimeout=30000&socketTimeout=1000
      driver-class-name: com.mysql.cj.jdbc.Driver
      username: root
      password:
      initial-size: 1
      min-idle: 1
      max-active: 1
      max-wait: 6000
      test-while-idle: true
      validation-query: select 1
      remove-abandoned: true
      async-init: true
      keep-alive: true
      filter:
        stat:
          log-slow-sql: true
          slow-sql-millis: 0
        slf4j:
          enabled: true
          statement-prepare-after-log-enabled: false

mybatis:
  configuration:
    map-underscore-to-camel-case: true # 驼峰与下划线互转支持
    config-location: classpath:mybatis-config.xml
    log-prefix: money
    log-impl: org.apache.ibatis.logging.stdout.StdOutImpl

# 日志打印级别
logging:
  level:
    root: info
    com.git.hui.boot.db.mapper.*: debug
    org.springframework.jdbc.core: debug
    com.alibaba.druid: debug

关于上面配置的一些细节，后面进行细说

我们创建一个用于测试的数据库

1
2
3
4
5
6
7
8
9
10
11
12
drop table `money` if exists;

CREATE TABLE `money` (
  `id` int(11) unsigned NOT NULL AUTO_INCREMENT,
  `name` varchar(20) NOT NULL DEFAULT '' COMMENT '用户名',
  `money` int(26) NOT NULL DEFAULT '0' COMMENT '钱',
  `is_deleted` tinyint(1) NOT NULL DEFAULT '0',
  `create_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP COMMENT '创建时间',
  `update_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP COMMENT '更新时间',
  PRIMARY KEY (`id`),
  KEY `name` (`name`)
) ENGINE=InnoDB AUTO_INCREMENT=551 DEFAULT CHARSET=utf8mb4

对应的myabtis-config.xml，配置我们自定义的sql日志输出拦截器

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE configuration
        PUBLIC "-//ibatis.apache.org//DTD Config 3.1//EN"
        "http://mybatis.org/dtd/mybatis-3-config.dtd">
<configuration>
    <settings>
        <!-- 驼峰下划线格式支持 -->
        <setting name="mapUnderscoreToCamelCase" value="true"/>
    </settings>
    <typeAliases>
        <package name="com.git.hui.boot.mybatis.entity"/>
    </typeAliases>
    <plugins>
        <plugin interceptor="com.git.hui.boot.db.interceptor.SqlStateInterceptor"/>
    </plugins>


</configuration>

II. 实例

1. mybatis默认配置

我们先看一下mybatis的默认日志输出方案，首先写一个money数据库的db操作mapper

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
@Mapper
public interface MoneyMapper {

    /**
     * 保存数据，并保存主键id
     *
     * @param po
     * @return int
     */
    @Options(useGeneratedKeys = true, keyProperty = "po.id", keyColumn = "id")
    @Insert("insert into money (name, money, is_deleted) values (#{po.name}, #{po.money}, #{po.isDeleted})")
    int save(@Param("po") MoneyPo po);


    /**
     * 删除数据
     *
     * @param id id
     * @return int
     */
    @Delete("delete from money where id = #{id}")
    int delete(@Param("id") int id);

    /**
     * 主键查询
     *
     * @param id id
     * @return {@link MoneyPo}
     */
    @Select("select * from money where id = #{id}")
    @Results(id = "moneyResultMap", value = {
            @Result(property = "id", column = "id", id = true, jdbcType = JdbcType.INTEGER),
            @Result(property = "name", column = "name", jdbcType = JdbcType.VARCHAR),
            @Result(property = "money", column = "money", jdbcType = JdbcType.INTEGER),
            @Result(property = "isDeleted", column = "is_deleted", jdbcType = JdbcType.TINYINT),
            @Result(property = "createAt", column = "create_at", jdbcType = JdbcType.TIMESTAMP),
            @Result(property = "updateAt", column = "update_at", jdbcType = JdbcType.TIMESTAMP)})
    MoneyPo getById(@Param("id") int id);
}

接下来重点看一下，如需开启myabtis默认的sql日志输出，应该如何配置

1
2
3
4
5
6
mybatis:
  configuration:
    map-underscore-to-camel-case: true # 驼峰与下划线互转支持
    config-location: classpath:mybatis-config.xml
    log-prefix: money
    log-impl: org.apache.ibatis.logging.stdout.StdOutImpl

重点看上面的 mybatis.configuration.log-prefix 与 myabtis.configuration.log-impl 这里制定了日志输出的方式

但是请注意，通常我们的日志是基于logback/slf4j来输出，默认的mybati的sql日志输出是debug级别，所以要看到输出的sql日志，还需要配置一下日志输出级别（本项目的实例中是直接控制台输出，因此不配置下面的也没有问题）

1
2
3
4
5
# 日志打印级别
logging:
  level:
    root: info # 默认日志输出级别是info
    com.git.hui.boot.db.mapper.*: debug  # 这个制定mapper的相关日志输出级别为debug，即可以输出默认的mybatis配置

然后写个demo验证一下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
@Slf4j
@SpringBootApplication
public class Application {
    public Application(MoneyMapper mapper, JdbcTemplate jdbcTemplate) {
        MoneyPo po = new MoneyPo();
        po.setName("一灰");
        po.setMoney(10L);
        po.setIsDeleted(0);
        mapper.save(po);

        MoneyPo db = mapper.getById(po.getId());
        log.info("查询结果：{}", db);

        mapper.delete(po.getId());
        log.info("删除完成: {}", po);
    }


    public static void main(String[] args) {
        SpringApplication.run(Application.class);
    }
}

从上图可以看出，myabtis将具体的sql执行，返回的行数等信息进行了返回，但是这个sql，并不是一个可以直接执行的，还需要我们自己来拼装一下，为了解决这个问题，可以通过 https://book.hhui.top/sql.html 来进行sql的自动拼接

2. Druid日志输出

除了mybatis的默认日志之外，对于使用druid数据源的场景，也可以直接借助druid来打印执行日志

核心的配置如下

1
2
3
4
5
6
7
8
spring:
  datasource:
    druid:
      filter:
        slf4j:
          enabled: true
          statement-prepare-after-log-enabled: true
`

示例如下

1
2
Map map = jdbcTemplate.queryForMap("select * from money where id = ?", po.getId());
log.info("查询: {}", map);

druid的默认输出日志中，并没有将请求参数打印出来，其效果相比较于mybatis而言，信息更少一些

3. 基于Mybatis的Interceptor实现方案

默认的输出方案虽好，但是总有一些缺陷，如果有一些自定义的诉求，如日志输出的脱敏，不妨考虑下接下来的基于mybatis的拦截器的实现方案

如下面是一个自定义的日志输出拦截器, 相关知识点较多，有兴趣的小伙伴，推荐参考下文

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
@Slf4j
@Component
@Intercepts({@Signature(type = StatementHandler.class, method = "query", args = {Statement.class, ResultHandler.class}), @Signature(type = StatementHandler.class, method = "update", args = {Statement.class})})
public class SqlStateInterceptor implements Interceptor {
    @Override
    public Object intercept(Invocation invocation) throws Throwable {
        long time = System.currentTimeMillis();
        StatementHandler statementHandler = (StatementHandler) invocation.getTarget();
        String sql = buildSql(statementHandler);
        Object[] args = invocation.getArgs();
        String uname = "";
        if (args[0] instanceof HikariProxyPreparedStatement) {
            HikariProxyConnection connection = (HikariProxyConnection) ((HikariProxyPreparedStatement) invocation.getArgs()[0]).getConnection();
            uname = connection.getMetaData().getUserName();
        } else if (DruidCheckUtil.hasDruidPkg()) {
            if (args[0] instanceof DruidPooledPreparedStatement) {
                Connection connection = ((DruidPooledPreparedStatement) args[0]).getStatement().getConnection();
                if (connection instanceof MysqlConnection) {
                    Properties properties = ((MysqlConnection) connection).getProperties();
                    uname = properties.getProperty("user");
                }
            }
        }

        Object rs;
        try {
            rs = invocation.proceed();
        } catch (Throwable e) {
            log.error("error sql: " + sql, e);
            throw e;
        } finally {
            long cost = System.currentTimeMillis() - time;
            sql = this.replaceContinueSpace(sql);
            // 这个方法的总耗时
            log.info("\n\n ============= \nsql ----> {}\nuser ----> {}\ncost ----> {}\n ============= \n", sql, uname, cost);
        }

        return rs;
    }

    /**
     * 拼接sql
     *
     * @param statementHandler
     * @return
     */
    private String buildSql(StatementHandler statementHandler) throws NoSuchFieldException {
        BoundSql boundSql = statementHandler.getBoundSql();
        Configuration configuration = null;
        if (statementHandler.getParameterHandler() instanceof DefaultParameterHandler) {
            DefaultParameterHandler handler = (DefaultParameterHandler) statementHandler.getParameterHandler();
            Field field = handler.getClass().getDeclaredField("configuration");
            field.setAccessible(true);
            configuration = (Configuration) ReflectionUtils.getField(field, handler);
        }

        if (configuration == null) {
            return boundSql.getSql();
        }

        return getSql(boundSql, configuration);
    }


    /**
     * 生成要执行的SQL命令
     *
     * @param boundSql
     * @param configuration
     * @return
     */
    private String getSql(BoundSql boundSql, Configuration configuration) {
        String sql = boundSql.getSql();
        Object parameterObject = boundSql.getParameterObject();
        List<ParameterMapping> parameterMappings = boundSql.getParameterMappings();
        if (CollectionUtils.isEmpty(parameterMappings) || parameterObject == null) {
            return sql;
        }

        MetaObject mo = configuration.newMetaObject(boundSql.getParameterObject());
        for (ParameterMapping parameterMapping : parameterMappings) {
            if (parameterMapping.getMode() == ParameterMode.OUT) {
                continue;
            }

            //参数值
            Object value;
            //获取参数名称
            String propertyName = parameterMapping.getProperty();
            if (boundSql.hasAdditionalParameter(propertyName)) {
                //获取参数值
                value = boundSql.getAdditionalParameter(propertyName);
            } else if (configuration.getTypeHandlerRegistry().hasTypeHandler(parameterObject.getClass())) {
                //如果是单个值则直接赋值
                value = parameterObject;
            } else {
                value = mo.getValue(propertyName);
            }
            String param = Matcher.quoteReplacement(getParameter(value));
            sql = sql.replaceFirst("\\?", param);
        }
        sql += ";";
        return sql;
    }

    public String getParameter(Object parameter) {
        if (parameter instanceof String) {
            return "'" + parameter + "'";
        } else if (parameter instanceof Date) {
            // 日期格式化
            return "'" + format(((Date) parameter).getTime()) + "'";
        } else if (parameter instanceof java.util.Date) {
            // 日期格式化
            return "'" + format(((java.util.Date) parameter).getTime()) + "'";
        }
        return parameter.toString();
    }

    public static String format(long timestamp) {
        LocalDateTime time = LocalDateTime.ofInstant(Instant.ofEpochMilli(timestamp), ZoneId.systemDefault());
        return DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss.SSS").format(time);
    }

    /**
     * 替换连续的空白
     *
     * @param str
     * @return
     */
    private String replaceContinueSpace(String str) {
        StringBuilder builder = new StringBuilder(str.length());
        boolean preSpace = false;
        for (int i = 0, len = str.length(); i < len; i++) {
            char ch = str.charAt(i);
            boolean isSpace = Character.isWhitespace(ch);
            if (preSpace && isSpace) {
                continue;
            }

            if (preSpace) {
                // 前面的是空白字符，当前的不是空白字符
                preSpace = false;
                builder.append(ch);
            } else if (isSpace) {
                // 当前字符为空白字符，前面的那个不是的
                preSpace = true;
                builder.append(" ");
            } else {
                // 前一个和当前字符都非空白字符
                builder.append(ch);
            }
        }
        return builder.toString();
    }

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

    @Override
    public void setProperties(Properties properties) {
    }
}

然后将第一种测试用例再跑一下，实际输出如下

3. 小结

本文主要介绍了三种常见的sql日志输出方案，原则上推荐通过自定义的插件方式来实现更符合业务需求的sql日志打印；但是，掌握了默认的myabtis日志输出方案之后，我们就可以借助配置中心，通过动态添加/修改 logging.level.com.git.hui.boot.db.mapper.* 来动态设置日志输出级别，再线上问题排查、尤其时场景可以复现的场景时，会有奇效哦

III. 不能错过的源码和相关知识点

0. 项目

1. 微信公众号: 一灰灰Blog

尽信书则不如，以上内容，纯属一家之言，因个人能力有限，难免有疏漏和错误之处，如发现bug或者有更好的建议，欢迎批评指正，不吝感激

下面一灰灰的个人博客，记录所有学习和工作中的博文，欢迎大家前去逛逛

一灰灰blog


打赏 如果觉得我的文章对您有帮助，请随意打赏。
分享到