配置 p6spy log 输出应用最终执行的 sql 语句

在上一篇的 配置 mybatis 打印出执行的 sql 及返回的结果集 中, 说到了在 mybatis 中如何打印出执行的 sql, 但是还是遗留了一个问题, 也即是它的输出的 sql 并不是最终可执行的, 而是类似于 jdbc 那种 PrepareStatement 的形式, 参数的值是用问号代替的, 如下:

select * from user where username = ? and password = ?

虽然其参数值通常也会一起输出, 但如果我们对查询的结果有疑问, 想去数据库里自己执行看看, 就不得不自己去拼凑那些最终的 sql:

select * from user where username = 'admin' and password = '123456';

如果参数特别多的查询, 这会成为一个麻烦. 那么, 是否有方式可以直接输出最终的 sql 呢? 一种方式就是下面将要介绍的 p6spy log.

p6spy log 输出效果

先看其输出的效果:

26:33 #1607390793732 | took 7ms | statement | connection 0| url jdbc:p6spy:mysql://localhost:3306/code_sample?serverTimezone=GMT%2B8
select * from user where username = ? and password = ?
select * from user where username = 'admin' and password = '123456';
26:33 list size: 1

可以看到, 除了那种 PrepareStatement 的形式, 还有最终的 sql. 那么, 要如何去实现这样的效果呢?

另注: 这里的日志布局我启用了一种极简的风格, 只有"分钟:秒数", 具体见 配置简化开发阶段日志输出布局 的介绍.

p6spy log 配置

首先需要引入其依赖, 在 maven 的 pom.xml 文件中加入其依赖:

<dependency>
    <groupId>p6spy</groupId>
    <artifactId>p6spy</artifactId>
    <version>3.9.1</version>
</dependency>

如果你使用其它方式, 如 gradle, 或直接引入 jar 包的方式, 请参考其官网的说明: https://p6spy.readthedocs.io/en/latest/install.html

基本配置

然后是数据库驱动需要换成 p6spy 的驱动及 url, 这里以 mysql 为例, 给出在 application-dev.properties 中的配置:

# p6spy log datasource driver
#spring.datasource.driver-class-name=com.mysql.cj.jdbc.Driver
spring.datasource.driver-class-name=com.p6spy.engine.spy.P6SpyDriver

# p6spy log datasource url
#spring.datasource.url=jdbc:mysql://localhost:3306/code_sample?serverTimezone=GMT%2B8
spring.datasource.url=jdbc:p6spy:mysql://localhost:3306/code_sample?serverTimezone=GMT%2B8

作为对比, 注释的配置为原始的配置.

注: 其它的数据库请参考其 github 及官网的说明: https://github.com/p6spy/p6spy 和 https://p6spy.readthedocs.io/en/latest/index.html

另注: 上述配置建议放在你的本地开发环境配置文件中, 通常为 application-dev.properties, 关于 spring-boot 的 分环境配置 的 profile 机制, 如不熟悉请自行查阅网络了解.

警告: 输出 sql 特性通常只是在本地开发调试阶段启动, 如果在生产环境也延续上述配置, 可能导致严重的性能问题!

最后是 p6spy log 本身的一些配置, 在一个叫 spy.properties 的文件中, java 工程里将其放置在 src/resources 目录根下即可, 一些关键的配置及说明如下:

#################################################################
# P6Spy Options File                                            #
# See documentation for detailed instructions                   #
# https://p6spy.readthedocs.io/en/latest/configandusage.html    #
#################################################################

# 根据你实际使用的调整
# 输出到 slf4j 
appender=com.p6spy.engine.spy.appender.Slf4JLogger

# 输出到 stdout
#appender=com.p6spy.engine.spy.appender.StdoutLogger

# 输出到 file
#appender=com.p6spy.engine.spy.appender.FileLogger
# 如果不配置, 默认会在当前工程下生成一个叫 spy.log 的文件
#logfile=C:/log/p6spy/spy.log
# 追加模式, 设置 false 则每次清空文件
#append=true

# 使用多行格式化. 如果使用默认的, 所有的信息会挤在一行, 比较难看
logMessageFormat=com.p6spy.engine.spy.appender.MultiLineFormat

#logMessageFormat=P6SpyLogger

默认的格式化配置

默认的格式化输出内容很多, 而且挤在一行, 其具体格式内容如下:

current time|execution time|category|connection id|datasource url|statement SQL String|effective SQL string

包括当前时间, 执行时间, 类别, 连接 id, 数据源 url, statement sql 和 最终有效的 sql. 输出很长, 不好看, 而且最关键的最终的 sql 语句被挤到最右边去了, 需要拖动才能看到:

26:33 #1607390793732 | took 7ms | statement | connection 0| url jdbc:p6spy:mysql://localhost:3306/code_sample?serverTimezone=GMT%2B8 | select * from user where username = ? and password = ? | select * from user where username = 'admin' and password = '123456';
26:33 list size: 1

多行输出格式化配置

如果想让最终输出的 sql 比较清晰易读, 可以使用一个预定义的多行输出格式化配置.

具体方式是在 spy.properties 文件中定义 logMessageFormat 属性的值为 com.p6spy.engine.spy.appender.MultiLineFormat, 如下所示:

# ... 其余配置略, 见前述内容

# 使用多行格式化. 如果使用默认的, 所有的信息会挤在一行, 比较难看
logMessageFormat=com.p6spy.engine.spy.appender.MultiLineFormat

之后, 输出即可达到文章开头处的换行输出效果:

26:33 #1607390793732 | took 7ms | statement | connection 0| url jdbc:p6spy:mysql://localhost:3306/code_sample?serverTimezone=GMT%2B8
select * from user where username = ? and password = ?
select * from user where username = 'admin' and password = '123456';
26:33 list size: 1

自定义格式化配置

最后, 如果觉得多行的输出还是比较啰嗦, 很多信息你不想看到, 你也可以自定义格式化输出, 在 spy.properties 的文件中, 使用以下配置:

# ... 其余配置略, 见前述内容

# 使用多行格式化. 如果使用默认的, 所有的信息会挤在一行, 比较难看
#logMessageFormat=com.p6spy.engine.spy.appender.MultiLineFormat

# 自定义输出
logMessageFormat=com.p6spy.engine.spy.appender.CustomLineFormat
customLogMessageFormat=\n\nstatement sql:\t%(effectiveSql)\nfinal sql:\t\t%(sql)\n

有两点需要注意:

1. logMessageFormat 属性使用 com.p6spy.engine.spy.appender.CustomLineFormat.
2. customLogMessageFormat 属性定义需要的格式.

在 customLogMessageFormat 中, 除直接量被直接支持外(如"statement sql", “final sql”), 还支持一些特殊的空白符如换行符(\n), 制表符(\t), 以及 p6spy 提供的变量占位符(以 %(XXX) 的形式).

在上述格式化配置中, 只输出了 %(effectiveSql) 以及 %(sql) 这两个比较有价值的信息, 其余则忽略了.

其它一些变量占位符还有如: %(connectionId), %(currentTime), %(executionTime), %(category), %(effectiveSql), %(effectiveSqlSingleLine), %(sql), %(sqlSingleLine) 等.

其中诸如 %(sqlSingleLine) 之类的会把多余的换行符去掉, 最终格式化为一行. 如果是 xml 映射的那种多行 sql, 最终会格式化为一行去显示

更多占位符的详细含义参考其官方文档: https://p6spy.readthedocs.io/en/latest/configandusage.html#customlogmessageformat

最终的输出效果如下:

30:48 HikariPool-1 - Starting...
30:48 HikariPool-1 - Start completed.
30:48 Began transaction (1) for test context [DefaultTestContext@34c01041 testClass = UserDaoTest, testInstance = net.xiaogd.sample.boot.p6spylog.dao.user.UserDaoTest@53941c2f, testMethod = testP6spyLog@UserDaoTest, testException = [null], mergedContextConfiguration = [MergedContextConfiguration@76f4b65 testClass = UserDaoTest, locations = '{}', classes = '{class net.xiaogd.sample.boot.p6spylog.AppApplication}', contextInitializerClasses = '[]', activeProfiles = '{}', propertySourceLocations = '{}', propertySourceProperties = '{org.mybatis.spring.boot.test.autoconfigure.MybatisTestContextBootstrapper=true}', contextCustomizers = set[[ImportsContextCustomizer@c94fd30 key = [org.springframework.boot.autoconfigure.cache.CacheAutoConfiguration, org.springframework.boot.autoconfigure.flyway.FlywayAutoConfiguration, org.springframework.boot.autoconfigure.jdbc.DataSourceAutoConfiguration, org.springframework.boot.autoconfigure.jdbc.DataSourceTransactionManagerAutoConfiguration, org.springframework.boot.autoconfigure.jdbc.JdbcTemplateAutoConfiguration, org.springframework.boot.autoconfigure.liquibase.LiquibaseAutoConfiguration, org.springframework.boot.autoconfigure.transaction.TransactionAutoConfiguration, org.mybatis.spring.boot.autoconfigure.MybatisLanguageDriverAutoConfiguration, org.mybatis.spring.boot.autoconfigure.MybatisAutoConfiguration, org.springframework.boot.test.autoconfigure.jdbc.TestDatabaseAutoConfiguration]], org.springframework.boot.test.context.filter.ExcludeFilterContextCustomizer@dc9876b, org.springframework.boot.test.json.DuplicateJsonObjectContextCustomizerFactory$DuplicateJsonObjectContextCustomizer@a1f72f5, org.springframework.boot.test.mock.mockito.MockitoContextCustomizer@0, org.springframework.boot.test.autoconfigure.OverrideAutoConfigurationContextCustomizerFactory$DisableAutoConfigurationContextCustomizer@2bec854f, org.springframework.boot.test.autoconfigure.actuate.metrics.MetricsExportContextCustomizerFactory$DisableMetricExportContextCustomizer@205d38da, org.springframework.boot.test.autoconfigure.filter.TypeExcludeFiltersContextCustomizer@351584c0, org.springframework.boot.test.autoconfigure.properties.PropertyMappingContextCustomizer@ed3940d1, org.springframework.boot.test.autoconfigure.web.servlet.WebDriverContextCustomizerFactory$Customizer@4e928fbf, org.springframework.boot.test.context.SpringBootTestArgs@1, org.springframework.boot.test.context.SpringBootTestWebEnvironment@0], contextLoader = 'org.springframework.boot.test.context.SpringBootContextLoader', parent = [null]], attributes = map[[empty]]]; transaction manager [org.springframework.jdbc.support.JdbcTransactionManager@73041b7d]; rollback [true]
30:49 

statement sql:	select * from user where username = ? and password = ?
final sql:		select * from user where username = 'admin' and password = '123456'

30:49 list size: 1

以上格式化输出, 为突出 sql 及为了对齐等考虑, 使用了较多的换行及制表符, 读者可根据自身需要取舍.

更多的配置参考其官网的说明: https://p6spy.readthedocs.io/en/latest/configandusage.html

在以上配置完成后, 执行 sql 查询相关操作时, 就能打印出前述的输出效果了.

其它测试相关的代码

测试类代码如下,

package net.xiaogd.sample.boot.p6spylog.dao.user;

import lombok.extern.slf4j.Slf4j;
import net.xiaogd.sample.boot.p6spylog.entity.User;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.extension.ExtendWith;
import org.mybatis.spring.boot.test.autoconfigure.MybatisTest;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.test.autoconfigure.jdbc.AutoConfigureTestDatabase;
import org.springframework.test.context.junit.jupiter.SpringExtension;

import java.util.List;

@Slf4j
@ExtendWith(SpringExtension.class)
@MybatisTest
@AutoConfigureTestDatabase(replace = AutoConfigureTestDatabase.Replace.NONE)
public class UserDaoTest {

	@Autowired
	private UserDao userDao;

	@Test
	public void testP6spyLog() throws Exception {
		List<User> list = userDao.findUserByUsernameAndPassword("admin", "123456");
        log.info("list size: {}", list.size());
	}
}

为加速测试启动, 避免加载与 Dao 无关的 bean, 这里使用了 @MybatisTest 注解. 其相关模块 mybatis-spring-boot-starter-test 的 maven 依赖如下:

<dependency>
    <groupId>org.mybatis.spring.boot</groupId>
    <artifactId>mybatis-spring-boot-starter-test</artifactId>
    <scope>test</scope>
    <version>2.1.4</version>
</dependency>

另注: 这里使用了最新的 Junit 5, 而不是传统的 Junit 4 的方式.

关于两者的区别, 请参考 Junit 官网的迁移指南: https://junit.org/junit5/docs/current/user-guide/#migrating-from-junit4

在上述代码中, 一个主要区别是 @ExtendWith(SpringExtension.class) 取代了 junit 4 的 @RunWith(SpringRunner.class)

Dao 类如下, 这里为方便, 简单使用了注解方式:

package net.xiaogd.sample.boot.p6spylog.dao.user;

import net.xiaogd.sample.boot.p6spylog.entity.User;
import org.apache.ibatis.annotations.Mapper;
import org.apache.ibatis.annotations.Select;
import org.springframework.stereotype.Repository;

import java.util.List;

@Mapper
@Repository
public interface UserDao {
    @Select("select * from user where username = #{username} and password = #{password}")
	List<User> findUserByUsernameAndPassword(String username, String password);
}

注: 如上 @Repository 注解不是必要的, 但 Idea IDE 如果没有相关插件支持可能会导致一些警告或报错信息, 加上该注解可以避免报错.

输出最终的 sql 还有其它的方式, 比如如果你使用了 druid 连接池, 它也有相关的配置能输出最终的 sql; 另外还有如果你使用的是 log4j, 还有 log4jdbc spy log 的方式也能输出最终的 sql.

由于篇幅关系及与本篇主题不符, 这里不一一介绍. 如果你有相关需求, 欢迎留言, 关于使用 p6spy log 输出最终 sql 的介绍就到这里.