目标记录每次请求内的http、es、mysql耗时,本篇讨论mysql部分
为什么说要探索,这不是很简单的事么?但是能满足以下几点么?
- 能记录limit等参数
- 能将参数和sql写一起,能直接使用
- 能记录耗时
- 能计数累加,统计一次请求中sql执行的总数和总耗时
spring原生能力
1 | ini复制代码logging.level.org.hibernate.SQL=debug |
通过上面两条配置。
- ✔️可以显示sql.
- ❌不能和参数一行显示
- ❌不能显示limit参数
- ❌不能计数和记录耗时
1 | csharp复制代码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=? |
原生log+org.hibernate.EmptyInterceptor
org.hibernate.EmptyInterceptor
提供钩子,hibernate本身提供entity的curd钩子。重写EmptyInterceptor
方法,可以实现计数。但是onPrepareStatement
方法只是装配sql前的事件,而且不是完整的sql。
- ✔️ 可以显示sql
- ❌ 不能和参数一行显示
- ❌ 不能显示limit参数
- ✔️ 能计数
- ❌ 不能记录耗时
1 | ini复制代码spring.jpa.properties.hibernate.ejb.interceptor=com.vison.itdoc.config.HibernateInterceptor |
1 | java复制代码public class HibernateInterceptor extends EmptyInterceptor { |
log4jdbc
log4jdbc能很好的解决sql完整显示和记录耗时的问题
1 | vbnet复制代码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_, |
还能够定义超过1定时间的执行sql记录为error类型。
1 | xml复制代码 <dependency> |
1 | ini复制代码spring.datasource.driver-class-name: net.sf.log4jdbc.DriverSpy |
注意需要添加spring.datasource.driver-class-name
和更改 spring.datasource.url
将jdbc改为 jdbc:log4jdbc
log4jdbc.properties可以定义更多配置
1 | ini复制代码#配置为需要记录的包或类匹配路径 |
- ✔️ 可以显示sql
- ✔️ 能和参数一起显示
- ✔️ 能显示limit参数
- ✔️ 能计数
- ✔️ 能记录单个sql耗时
- ❌ 不能统计总耗时
不足的是,单纯log4jdbc并不能满足所有。理论上log4jdbc+org.hibernate.EmptyInterceptor可以满足需求了
P6Spy
测试完毕,发现P6Spy目前最能满足需求:
- ✔️ 可以显示sql
- ✔️ 不能和参数一起显示
- ✔️ 不能显示limit参数
- ✔️ 能计数
- ✔️ 不能记录耗时
- ✔️ 支持curd事件前后钩子,钩子参数返回sql和执行耗时及异常信息🚀
1 | xml复制代码 <dependency> |
同log4jdbc
需要改driver和url
1 | ini复制代码spring.datasource.driver-class-name=com.p6spy.engine.spy.P6SpyDriver |
psy.properties可以定义更多配置
1 | ini复制代码#modulelist=com.p6spy.engine.spy.P6SpyFactory,com.p6spy.engine.logging.P6LogFactory,com.p6spy.engine.outage.P6OutageFactory |
正常使用默认配置就可以显示出sql和耗时信息
1 | csharp复制代码 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
1 | java复制代码public class CustomeP6Factory implements com.p6spy.engine.spy.P6Factory { |
自定义事件
1 | java复制代码public class P6spyListener extends JdbcEventListener { |
可以看到,我在自定义事件中进行了sql计数.于是我可以在请求结束时打印每次请求的总sql执行次数。
1 | java复制代码public class RequestInitInterceptor implements HandlerInterceptor { |
由于事件参数还给出了timeElapsedNanos
,最终我们还能统计出所有sql执行的耗时。这样一来我们就能看出一次请求内,最耗时的操作具体是什么。达到类似以下效果:
配合自定义DispatcherServlet
可以记录请求数据、返回数据、sql执行数据次数、耗时
1 | csharp复制代码2021-03-01 11:19:40.694 || DEBUG || c.v.i.c.LoggableDispatcherServlet || || GET "/admin/posts?page=1&rows=10&sort=id&desc=false", parameters={masked} |
本文转载自: 掘金