spring-boot記錄sql探索

目標記錄每次請求內的http、es、mysql耗時，本篇討論mysql部分

為什麼說要探索，這不是很簡單的事麼？但是能滿足以下幾點麼？

• 能記錄limit等引數
• 能將引數和sql寫一起，能直接使用
• 能記錄耗時
• 能計數累加,統計一次請求中sql執行的總數和總耗時

spring原生能力

logging.level.org.hibernate.SQL=debug
logging.level.org.hibernate.type.descriptor.sql.BasicBinder=trace

通過上面兩條配置。

• ✔️可以顯示sql.
• ❌不能和引數一行顯示
• ❌不能顯示limit引數
• ❌不能計數和記錄耗時

2021-02-23 19:35:42.932 DEBUG 97586 --- [  restartedMain] org.hibernate.SQL                        : select admin0_.id as id1_0_, admin0_.create_time as create_t2_0_, admin0_.modify_time as modify_t3_0_, admin0_.email as email4_0_, admin0_.password as password5_0_, admin0_.status as status6_0_, admin0_.username as username7_0_ from admin admin0_ where admin0_.username=?
2021-02-23 19:35:42.949 TRACE 97586 --- [  restartedMain] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [VARCHAR] - [root]

原生log+org.hibernate.EmptyInterceptor

org.hibernate.EmptyInterceptor提供鉤子，hibernate本身提供entity的curd鉤子。重寫EmptyInterceptor方法，可以實現計數。但是onPrepareStatement方法只是裝配sql前的事件，而且不是完整的sql。

• ✔️ 可以顯示sql
• ❌ 不能和引數一行顯示
• ❌ 不能顯示limit引數
• ✔️ 能計數
• ❌ 不能記錄耗時

spring.jpa.properties.hibernate.ejb.interceptor=com.vison.itdoc.config.HibernateInterceptor

public class HibernateInterceptor extends EmptyInterceptor {
    
    @Override
    public boolean onLoad(Object entity, Serializable id, Object[] state, String[] propertyNames, Type[] types) {
//        Log.info("onload...", entity)
        return true;
    }
    
    @Override
    public String onPrepareStatement(String string) {
        // count++
        return INSTANCE.onPrepareStatement(string);
    }
    
    @Override
    public void afterTransactionCompletion(Transaction t) {
        INSTANCE.afterTransactionCompletion(t);
        Log.info("after trans complete", t);
    }
    
}

log4jdbc

log4jdbc能很好的解決sql完整顯示和記錄耗時的問題

2021-02-23 19:59:13.709  INFO 97586 --- [nio-8081-exec-1] jdbc.sqltiming                           : select posts0_.id as id1_2_, posts0_.create_time as create_t2_2_, posts0_.modify_time as modify_t3_2_, 
posts0_.content as content4_2_, posts0_.title as title5_2_ from posts posts0_ where 1=1 order 
by posts0_.id asc limit 10 ;
 {executed in 1 msec}

還能夠定義超過1定時間的執行sql記錄為error型別。

        <dependency>
            <groupId>com.googlecode.log4jdbc</groupId>
            <artifactId>log4jdbc</artifactId>
            <version>1.2</version>
            <scope>runtime</scope>
        </dependency>

spring.datasource.driver-class-name: net.sf.log4jdbc.DriverSpy
#使用log4jdbc後mysql的url
spring.datasource.url=jdbc:log4jdbc:mysql://localhost:3306/xxxx?useUnicode=true&characterEncoding=UTF-8
#使用log4jdbc後oracle的url
#spring.datasource.url: jdbc:log4jdbc:oracle:thin:@127.0.0.1:1521:orcl

注意需要新增spring.datasource.driver-class-name 和更改 spring.datasource.url 將jdbc改為 jdbc:log4jdbc

log4jdbc.properties可以定義更多配置

#配置為需要記錄的包或類匹配路徑
#log4jdbc.debug.stack.prefix=com.drp
#log4jdbc載入的drivers (驅動名)
#log4jdbc.drivers=oracle.jdbc.OracleDriver
log4jdbc.auto.load.popular.drivers=true
#在日誌中顯示warn警告
log4jdbc.statement.warn=true
#毫秒值.執行時間超過該值的SQL語句將被記錄為warn級別.
log4jdbc.sqltiming.warn.threshold=2000
#毫秒值.執行時間超過該值的SQL語句將被記錄為error級別.
log4jdbc.sqltiming.error.threshold=3000
#是把boolean記錄為 'true'/'false' 還是 1/0. 預設設定為false,不啟用,為了移植性.
#log4jdbc.dump.booleanastruefalse=true
#輸出的sql,一行最大的字元數，預設90. 以後新版可能為0
#log4jdbc.dump.sql.maxlinelength=90
#如果在除錯模式下轉儲，則轉儲整個堆疊跟蹤  預設false
log4jdbc.dump.fulldebugstacktrace=false

#是否記錄某些型別的語句，預設true
log4jdbc.dump.sql.select=true
log4jdbc.dump.sql.insert=true
log4jdbc.dump.sql.delete=true
log4jdbc.dump.sql.update=true
log4jdbc.dump.sql.create=true

#輸出sql末尾處加入分號，預設false
log4jdbc.dump.sql.addsemicolon=true

#將此設定為false以不修剪已記錄的SQL
log4jdbc.trim.sql=true
#將此設定為false不刪除額外的空行
log4jdbc.trim.sql.extrablanklines=true

#log4jdbc.suppress.generated.keys.exception=false

• ✔️ 可以顯示sql
• ✔️ 不能和引數一起顯示
• ✔️ 不能顯示limit引數
• ❌ 能計數
• ✔️ 能記錄單個sql耗時
• ❌ 不能統計總耗時

不足的是，單純log4jdbc並不能滿足所有。理論上log4jdbc+org.hibernate.EmptyInterceptor可以滿足需求了

P6Spy

測試完畢，發現P6Spy目前最能滿足需求：

• ✔️ 可以顯示sql
• ✔️ 不能和引數一起顯示
• ✔️ 不能顯示limit引數
• ✔️ 能計數
• ✔️ 不能記錄耗時
• ✔️ 支援curd事件前後鉤子，鉤子引數返回sql和執行耗時及異常資訊?

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

同log4jdbc需要改driver和url

spring.datasource.driver-class-name=com.p6spy.engine.spy.P6SpyDriver
spring.datasource.url=jdbc:p6spy:mysql://localhost:3306/test?useLegacyDatetimeCode=false&serverTimezone=UTC

psy.properties可以定義更多配置

#modulelist=com.p6spy.engine.spy.P6SpyFactory,com.p6spy.engine.logging.P6LogFactory,com.p6spy.engine.outage.P6OutageFactory
modulelist=com.vison.itdoc.config.CustomeP6Factory,com.p6spy.engine.logging.P6LogFactory,com.p6spy.engine.outage.P6OutageFactory
#moduelist很關鍵，我這裡使用了自定義的Factory，因為我需要自定義event
appender=com.p6spy.engine.spy.appender.Slf4JLogger
logMessageFormat=com.p6spy.engine.spy.appender.CustomLineFormat
customLogMessageFormat=%(executionTime) ms|%(category)|%(sql)
excludecategories=result,resultset,info,debug

正常使用預設配置就可以顯示出sql和耗時資訊

 4 ms|statement|select admin0_.id as id1_0_, admin0_.create_time as create_t2_0_, admin0_.modify_time as modify_t3_0_, admin0_.email as email4_0_, admin0_.password as password5_0_, admin0_.status as status6_0_, admin0_.username as username7_0_ from admin admin0_ where admin0_.username='root'

可以看到，耗時資訊和實際引數

自定義事件

modulelist=com.p6spy.engine.spy.P6SpyFactory改成自定義Factory

自定義Factory

public class CustomeP6Factory implements com.p6spy.engine.spy.P6Factory {

    @Override
    public P6LoadableOptions getOptions(P6OptionsRepository optionsRepository) {
        return new P6SpyOptions(optionsRepository);
    }

    @Override
    public JdbcEventListener getJdbcEventListener() {
        return new P6spyListener(); //使用自定義Listener
    }

}

自定義事件

public class P6spyListener extends JdbcEventListener {

    @Override
    public void onAfterExecuteQuery(PreparedStatementInformation statementInformation, long timeElapsedNanos, SQLException e) {
        App.sqlCount.incrementAndGet();
        Log.info("execute query...", statementInformation.getSqlWithValues());
    }

    @Override
    public void onAfterExecuteUpdate(PreparedStatementInformation statementInformation, long timeElapsedNanos, int rowCount, SQLException e) {
        App.sqlCount.incrementAndGet();
        Log.info("execute update..", statementInformation.getSqlWithValues());
    }

    @Override
    public void onAfterExecute(StatementInformation statementInformation, long timeElapsedNanos, String sql, SQLException e) {
        Log.info("execute..", statementInformation.getSqlWithValues());
    }

}

可以看到，我在自定義事件中進行了sql計數.於是我可以在請求結束時列印每次請求的總sql執行次數。

public class RequestInitInterceptor implements HandlerInterceptor {

    public RequestInitInterceptor() {
    }

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler)
            throws Exception {
        App._uniq_req_no = UUID.randomUUID().toString();
        App.sqlCount = new AtomicInteger(0);
        Log.setMsgTraceNo(App._uniq_req_no);
        Log.info("request start...", handler);
        return true;
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex)
            throws Exception {
        Log.info(String.format("finish request sql執行次數:%s", App.sqlCount));
    }

}

由於事件引數還給出了timeElapsedNanos,最終我們還能統計出所有sql執行的耗時。這樣一來我們就能看出一次請求內，最耗時的操作具體是什麼。達到類似以下效果：

參考

• Counting Queries per Request with Hibernate and Spring
• register an event handler