Spring Boot DATA JPA抓取SQL執行時的傳遞進去的引數資訊
阿新 • • 發佈：2019-02-19
在系統開發過程中，涉及到資料庫操作都是SQL的天下，基於ORM的各類框架來簡化開發；在JPA/Hibernate方案中，只提供了SQL的列印輸出，但並未輸入SQL的引數值是多少，這裡將解決這個問題，告知具體如何來實現這個操作。
1. 技術棧的介紹
JDK 1.8, Spring Boot 2.0.3.RELEASE, Mysql 5.7
2. 依賴包
Spring Boot中的JPA依賴包：
<dependency> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter</artifactId> </dependency> <dependency> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-web</artifactId> </dependency> <dependency> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-test</artifactId> <scope>test</scope> </dependency> <dependency> <groupId>mysql</groupId> <artifactId>mysql-connector-java</artifactId> </dependency> <dependency> <groupId>com.googlecode.log4jdbc</groupId> <artifactId>log4jdbc</artifactId> <version>1.2</version> </dependency>
3. log4jdbc的介紹
log4jdbc使用SLF4J（Simple Logging Facade For Java）作為日誌系統。特性：
- 支援JDBC3和JDBC4，其中JDBC3對應於JDK 1.4 or 1.5，JDBC4要求JDK 1.6或以上。
- 支援現有大部分JDBC驅動。
- 易於配置（在大部分情況下，只需要改變驅動類名並在jdbc url前加上”jdbc:log4“，設定好日誌輸出級別）。
- 能夠自動把SQL變數值加到SQL輸出日誌中，改進易讀性和方便除錯。
- 能夠快速標識出應用程式中執行比較慢的SQL語句。
- 能夠生成SQL連線數資訊幫助識別連線池/執行緒問題。
綜合一句話，log4jdbc可以幫我們實現一個抓取SQL中實際使用值的功能。
4. Spring Boot示例
application.properties內容：
spring.datasource.driver-class-name = net.sf.log4jdbc.DriverSpy spring.datasource.url= jdbc:log4jdbc:mysql://127.0.0.1:3306/demo?useUnicode=yes&characterEncoding=UTF-8&useSSL=false spring.datasource.username = root spring.datasource.password = 123123 spring.datasource.type=com.zaxxer.hikari.HikariDataSource spring.datasource.initialization-mode=never spring.datasource.hikari.minimum-idle=0 spring.datasource.hikari.idle-timeout=10800000 spring.datasource.hikari.max-lifetime=21600000 spring.datasource.hikari.connection-timeout=6000 spring.datasource.hikari.initialization-fail-timeout=0 spring.datasource.hikari.data-source-properties.useUnicode=true spring.datasource.hikari.data-source-properties.characterEncoding=utf8 spring.datasource.hikari.data-source-properties.useSSL=false spring.datasource.hikari.data-source-properties.cachePrepStmts=true spring.datasource.hikari.data-source-properties.prepStmtCacheSize=512 spring.datasource.hikari.data-source-properties.allowMultiQueries=true spring.datasource.hikari.data-source-properties.useLocalSessionState=true spring.datasource.hikari.data-source-properties.prepStmtCacheSqlLimit=81920 spring.datasource.hikari.data-source-properties.rewriteBatchedStatements=false spring.datasource.hikari.data-source-properties.useOldAliasMetadataBehavior=true spring.datasource.hikari.data-source-properties.createDatabaseIfNotExist=true spring.jpa.open-in-view=false spring.jpa.generate-ddl=true spring.jpa.hibernate.ddl-auto=update spring.jpa.properties.hibernate.hbm2ddl.import_files=data.sql spring.jpa.show-sql=true
這裡需要注意的是mysql的原來的驅動程式.driver-class-name 和mysql的url
spring.datasource.driver-class-name = net.sf.log4jdbc.DriverSpy
spring.datasource.url= jdbc:log4jdbc:mysql://127.0.0.1:3306/demo?useUnicode=yes&characterEncoding=UTF-8&useSSL=false
將被 net.sf.log4jdbc.DriverSpy來替代，可以理解為DriverSpy做為mysql驅動的代理來捕捉SQL的資訊。
資料庫連線的URL需要進行修改為：
原來的： jdbc:mysql://localhost:3306/mealsystem
現在的： jdbc:log4jdbc:mysql://localhost:3306/mealsystem
除此之外，無需額外的變化需求，其餘程式碼都一致即可獲得執行中的SQL資訊。
2018-09-04 11:18:52.429 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. Connection.isValid(5) returned true
2018-09-04 11:18:52.429 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. Connection.getAutoCommit() returned true
2018-09-04 11:18:52.429 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. Connection.setAutoCommit(false) returned
Hibernate: select userpo0_.id as id1_0_0_, userpo0_.address as address2_0_0_, userpo0_.books as books3_0_0_, userpo0_.name as name4_0_0_, userpo0_.phone as phone5_0_0_ from user userpo0_ where userpo0_.id=?
2018-09-04 11:18:52.468 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. PreparedStatement.new PreparedStatement returned
2018-09-04 11:18:52.468 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. Connection.prepareStatement(select userpo0_.id as id1_0_0_, userpo0_.address as address2_0_0_, userpo0_.books as books3_0_0_, userpo0_.name as name4_0_0_, userpo0_.phone as phone5_0_0_ from user userpo0_ where userpo0_.id=?) returned net.sf.log4jdbc.PreparedStatementSpy@810bf7d
2018-09-04 11:18:52.475 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. PreparedStatement.setInt(1, 1) returned
2018-09-04 11:18:52.477 INFO 10184 --- [nio-8081-exec-2] jdbc.sqlonly : select userpo0_.id as id1_0_0_, userpo0_.address as address2_0_0_, userpo0_.books as books3_0_0_,
userpo0_.name as name4_0_0_, userpo0_.phone as phone5_0_0_ from user userpo0_ where userpo0_.id=1
2018-09-04 11:18:52.478 INFO 10184 --- [nio-8081-exec-2] jdbc.sqltiming : select userpo0_.id as id1_0_0_, userpo0_.address as address2_0_0_, userpo0_.books as books3_0_0_,
userpo0_.name as name4_0_0_, userpo0_.phone as phone5_0_0_ from user userpo0_ where userpo0_.id=1
{executed in 1 msec}
2018-09-04 11:18:52.481 INFO 10184 --- [nio-8081-exec-2] jdbc.resultset : 2. ResultSet.new ResultSet returned
2018-09-04 11:18:52.481 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. PreparedStatement.executeQuery() returned net.sf.log4jdbc.ResultSetSpy@2bb7b913
2018-09-04 11:18:52.489 INFO 10184 --- [nio-8081-exec-2] jdbc.resultset : 2. ResultSet.next() returned true
2018-09-04 11:18:52.498 INFO 10184 --- [nio-8081-exec-2] jdbc.resultset : 2. ResultSet.getString(address2_0_0_) returned bj0
2018-09-04 11:18:52.498 INFO 10184 --- [nio-8081-exec-2] jdbc.resultset : 2. ResultSet.wasNull() returned false
2018-09-04 11:18:52.498 INFO 10184 --- [nio-8081-exec-2] jdbc.resultset : 2. ResultSet.getString(books3_0_0_) returned [{"name": "c++", "price": 53.9}, {"name": "java", "price": 100}]
2018-09-04 11:18:52.498 INFO 10184 --- [nio-8081-exec-2] jdbc.resultset : 2. ResultSet.wasNull() returned false
2018-09-04 11:18:52.538 INFO 10184 --- [nio-8081-exec-2] jdbc.resultset : 2. ResultSet.getString(name4_0_0_) returned xiaoming
2018-09-04 11:18:52.538 INFO 10184 --- [nio-8081-exec-2] jdbc.resultset : 2. ResultSet.wasNull() returned false
2018-09-04 11:18:52.538 INFO 10184 --- [nio-8081-exec-2] jdbc.resultset : 2. ResultSet.getString(phone5_0_0_) returned ["15510062270", "15516676760"]
2018-09-04 11:18:52.538 INFO 10184 --- [nio-8081-exec-2] jdbc.resultset : 2. ResultSet.wasNull() returned false
2018-09-04 11:18:52.543 INFO 10184 --- [nio-8081-exec-2] jdbc.resultset : 2. ResultSet.next() returned false
2018-09-04 11:18:52.575 INFO 10184 --- [nio-8081-exec-2] jdbc.resultset : 2. ResultSet.close() returned
2018-09-04 11:18:52.576 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. PreparedStatement.getMaxRows() returned 0
2018-09-04 11:18:52.576 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. PreparedStatement.getQueryTimeout() returned 0
2018-09-04 11:18:52.576 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. PreparedStatement.close() returned
Hibernate: update user set address=?, books=?, name=?, phone=? where id=?
2018-09-04 11:18:52.596 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. PreparedStatement.new PreparedStatement returned
2018-09-04 11:18:52.596 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. Connection.prepareStatement(update user set address=?, books=?, name=?, phone=? where id=?) returned net.sf.log4jdbc.PreparedStatementSpy@741f652
2018-09-04 11:18:52.596 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. PreparedStatement.setString(1, "bj0") returned
2018-09-04 11:18:52.597 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. PreparedStatement.setString(2, "[{"name":"c++","price":53.9},{"name":"java","price":100.0}]") returned
2018-09-04 11:18:52.597 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. PreparedStatement.setString(3, "xiaoming") returned
2018-09-04 11:18:52.597 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. PreparedStatement.setString(4, "["15510062270","15516676760"]") returned
2018-09-04 11:18:52.597 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. PreparedStatement.setInt(5, 1) returned
2018-09-04 11:18:52.597 INFO 10184 --- [nio-8081-exec-2] jdbc.sqlonly : update user set address='bj0', books='[{"name":"c++","price":53.9},{"name":"java","price":100.0}]',
name='xiaoming', phone='["15510062270","15516676760"]' where id=1
2018-09-04 11:18:52.598 INFO 10184 --- [nio-8081-exec-2] jdbc.sqltiming : update user set address='bj0', books='[{"name":"c++","price":53.9},{"name":"java","price":100.0}]',
name='xiaoming', phone='["15510062270","15516676760"]' where id=1
{executed in 1 msec}
2018-09-04 11:18:52.598 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. PreparedStatement.executeUpdate() returned 1
2018-09-04 11:18:52.598 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. PreparedStatement.getMaxRows() returned 0
2018-09-04 11:18:52.598 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. PreparedStatement.getQueryTimeout() returned 0
2018-09-04 11:18:52.598 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. PreparedStatement.close() returned
2018-09-04 11:18:52.605 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. Connection.commit() returned
2018-09-04 11:18:52.605 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. Connection.setAutoCommit(true) returned
2018-09-04 11:18:52.607 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. Connection.clearWarnings() returned
2018-09-04 11:18:52.607 INFO 10184 --- [nio-8081-exec-2] jdbc.audit : 2. Connection.clearWarnings() returned
可以發現其select和update語句是有具體的值存在的，額外還有執行所使用的時間。
2018-09-04 11:18:52.478 INFO 10184 --- [nio-8081-exec-2] jdbc.sqltiming : select userpo0_.id as id1_0_0_, userpo0_.address as address2_0_0_, userpo0_.books as books3_0_0_,
userpo0_.name as name4_0_0_, userpo0_.phone as phone5_0_0_ from user userpo0_ where userpo0_.id=1
{executed in 1 msec}
2018-09-04 11:18:52.598 INFO 10184 --- [nio-8081-exec-2] jdbc.sqltiming : update user set address='bj0', books='[{"name":"c++","price":53.9},{"name":"java","price":100.0}]',
name='xiaoming', phone='["15510062270","15516676760"]' where id=1
{executed in 1 msec}
6. 參考資料
- http://www.cnblogs.com/xdp-gacl/p/4081848.html
- http://my.oschina.net/kzhou/blog/149532