Configure p6spy log to output the sql statement finally executed by the application

In the previous article, configuring mybatis to print out the executed sql and the returned result set, we talked about how to print out the executed sql in mybatis, but there is still a problem, that is, the output sql is not final executable , but similar to the PrepareStatement form of jdbc, the value of the parameter is replaced by a question mark, as follows:

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

Although its parameter values are usually output together, if we have doubts about the query results and want to go to the database to execute it ourselves, we have to piece together the final sql by ourselves:

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

If the query has too many parameters, this will become a trouble. So, is there a way to directly output the final sql? One way is the p6spy log that will be introduced below.

p6spy log output effect

First look at the effect of its output:

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

It can be seen that in addition to the form of PrepareStatement, there is also the final sql. So, how to achieve such an effect?

Another note: I have enabled a minimalist style for the log layout here, only “minutes:seconds”, for details, see the introduction of configuring the simplified development log output layout.

p6spy log configuration

First, you need to introduce its dependencies, and add its dependencies in maven’s pom.xml file:

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

If you use other methods, such as gradle, or directly import the jar package, please refer to the instructions on its official website: https://p6spy.readthedocs.io/en/latest/install.html

Basic configuration

Then the database driver needs to be replaced with the driver and url of p6spy. Here, taking mysql as an example, the configuration in application-dev.properties is given:

# 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+8
spring.datasource.url=jdbc:p6spy:mysql://localhost:3306/code_sample?serverTimezone=GMT+8

For comparison, the annotated configuration is the original configuration.

Note: For other databases, please refer to their github and official website instructions: https://github.com/p6spy/p6spy and https://p6spy.readthedocs.io/en/latest/index.html

Another note: The above configuration is recommended to be placed in your local development environment configuration file, usually application-dev.properties, about the sub-environment configuration profile mechanism of spring-boot , If you are not familiar with it, please refer to the Internet to find out.

Warning: The output sql feature is usually only enabled in the local development and debugging phase. If the above configuration is continued in the production environment, it may cause serious performance problems!

Finally, there are some configurations of p6spy log itself. In a file called spy.properties, it can be placed under the root of the src/resources directory in the java project. Some The key configuration and description are as follows:

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

# Adjust according to your actual use
# output to slf4j
appender=com.p6spy.engine.spy.appender.Slf4JLogger

# output to stdout
#appender=com.p6spy.engine.spy.appender.StdoutLogger

# output to file
#appender=com.p6spy.engine.spy.appender.FileLogger
# If not configured, a file called spy.log will be generated under the current project by default
#logfile=C:/log/p6spy/spy.log
# Append mode, set false to clear the file every time
#append=true

# Use multi-line formatting. If you use the default, all information will be squeezed into one line, which is ugly
logMessageFormat=com.p6spy.engine.spy.appender.MultiLineFormat

#logMessageFormat=P6SpyLogger

Default formatting configuration

The default formatted output has a lot of content and is squeezed into one line. The specific format content is as follows:

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

Including current time, execution time, category, connection id, data source url, statement sql and the final effective sql. The output is very long and ugly, and the most critical final sql statement is squeezed to the far right and needs to be dragged to see:

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

Multi-line output formatting configuration

If you want to make the final output sql clearer and easier to read, you can use a predefined multi-line output formatting configuration.

The specific way is to define the value of logMessageFormat attribute in spy.properties file as com.p6spy.engine.spy.appender.MultiLineFormat, as follows Show:

# ... The rest of the configuration is omitted, see the previous content

# Use multi-line formatting. If you use the default, all information will be squeezed into one line, which is ugly
logMessageFormat=com.p6spy.engine.spy.appender.MultiLineFormat

After that, the output can achieve the newline output effect at the beginning of the article:

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

Custom formatting configuration

Finally, if you feel that the multi-line output is still quite verbose, and you don’t want to see a lot of information, you can also customize the formatted output. In the spy.properties file, use the following configuration:

# ... The rest of the configuration is omitted, see the previous content

# Use multi-line formatting. If you use the default, all information will be squeezed into one line, which is ugly
#logMessageFormat=com.p6spy.engine.spy.appender.MultiLineFormat

# Custom output
logMessageFormat=com.p6spy.engine.spy.appender.CustomLineFormat
customLogMessageFormat=\\
\\
statement sql:\t%(effectiveSql)\\
final sql:\t\t%(sql)\\


There are two points to note:

  1. The logMessageFormat property uses com.p6spy.engine.spy.appender.CustomLineFormat.
  2. The customLogMessageFormat attribute defines the desired format.

In customLogMessageFormat, in addition to the direct quantity is directly supported (such as “statement sql”, “final sql”), it also supports some special blank characters such as newline character (\\
), the system Tabs (\t), and variable placeholders provided by p6spy (in the form of %(XXX)).

In the above formatting configuration, only the two valuable information %(effectiveSql) and %(sql) are output, and the rest are ignored.

Some other variable placeholders are: %(connectionId), %(currentTime), %(executionTime), %( category), %(effectiveSql), %(effectiveSqlSingleLine), %(sql), %(sqlSingleLine) etc.

Among them, such as %(sqlSingleLine) will remove the extra line breaks and finally format it into one line. If it is the multi-line sql mapped by xml, it will eventually be formatted into one line for display

For more detailed meanings of placeholders, refer to its official documentation: https://p6spy.readthedocs.io/en/latest/configandusage.html#customlogmessageformat

The final output is as follows:

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.My batisLanguageDriverAutoConfiguration, 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.OverrideAutoConfigurationContextCustomizerF actor$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.pro perties.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.springfra mework. 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

In the formatted output above, in order to highlight sql and alignment, etc., more newlines and tabs are used, and readers can choose according to their own needs.

For more configuration, refer to the instructions on its official website: https://p6spy.readthedocs.io/en/latest/configandusage.html

After the above configuration is completed, when executing sql query related operations, the aforementioned output effect can be printed out.

Other test-related code

The test class code is as follows,

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());
}
}

In order to speed up the test startup and avoid loading beans unrelated to Dao, the @MybatisTest annotation is used here. The maven dependencies of the related module mybatis-spring-boot-starter-test are as follows :

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

Another note: The latest Junit 5 is used here instead of the traditional Junit 4 way.

For the difference between the two, please refer to the migration guide on the Junit official website: https://junit.org/junit5/docs/current/user-guide/#migrating-from-junit4

In the above code, one major difference is that @ExtendWith(SpringExtension.class) replaces junit 4’s @RunWith(SpringRunner.class)

The Dao class is as follows, here for convenience, the annotation method is simply used:

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);
}

Note: The above @Repository annotation is not necessary, but if Idea IDE does not have relevant plug-in support, it may cause some warnings or error messages, adding this annotation can avoid error reporting.

There are other ways to output the final sql. For example, if you use the druid connection pool, it also has related configurations to output the final sql; in addition, if you use log4j, there is also log4jdbc spy log. final sql.

Due to space constraints and inconsistent with the theme of this article, I will not introduce them one by one here. If you have relevant needs, please leave a message. The introduction of using p6spy log to output the final sql is here.