关于java:springboot记录sql探索

指标记录每次申请内的 http、es、mysql 耗时，本篇探讨 mysql 局部

为什么说要摸索，这不是很简略的事么？然而能满足以下几点么？

能记录 limit 等参数
能将参数和 sql 写一起，能间接应用
能记录耗时
能计数累加, 统计一次申请中 sql 执行的总数和总耗时

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]

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 能很好的解决 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 目前最能满足需要：

✔️ 能够显示 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 执行的耗时。这样一来咱们就能看出一次申请内，最耗时的操作具体是什么。达到相似以下成果：

关于java:springboot记录sql探索

spring 原生能力

原生 log+org.hibernate.EmptyInterceptor

log4jdbc

P6Spy

自定义事件