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

介绍了如何使用 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 的介绍就到这里.