微服务架构 | 如何优化日志链路追踪输出 SQL 的执行效率?
导读:查看 SQL 的执行效率,不难想到使用 explain 分析慢查询,但是前提是你需要非常了解业务背景。否则很难精准定位到。
系统都是逐渐演进的,一个系统在运行中必须是根据场景逐渐地提高优化性能。高并发就是对资源的节约的考验,这种考验除了更换优秀和先进的技术,优化架构,还在于从小处出发,对尽可能节约的资源进行节约。
而在一个系统的数据访问中,系统的瓶颈往往是来自于数据库,因此我们要尽可能减少对数据库的访问!
一、背景
有没有遇到这种情况,领导突然安排一件事情:这几个接口压测指标太低需要针对性优化一下。
当然理想的情况下你对业务场景非常熟悉,可以大概定位问题来分析业务精准评估哪些 SQL 会有性能瓶颈。
然后开始百度:如何提高 SQL 执行效率?
通过 explain、show profile 和 trace 等诊断工具来分析慢查询。
但是大多数情况下业务线过长,不可能一个人完成。涉及到各种策略模式、监听动作。想直接定位到点还是需要输出请求发起后所触发的执行的 SQL 以及执行效率。这里效率单单指代 SQL 执行的时间。
目标明确后开始整活吧。
二、添加 JDBC 追踪
继续前一篇文章的话题:如何利用好日志链路追踪做性能分析?
![](https://static001.geekbang.org/infoq/87/874a233a2fbe56f5e23d7b93ae572bdf.webp?x-oss-process=image/resize,p_80/format,jpg)
▐ SQL 执行时间公式
要想处理此类问题首先的分析,SQL 执行时间计算如何来划分?SQL 的语句执行过程大致如下图所示。
![](https://static001.geekbang.org/infoq/c2/c29e708c05a51a7a262585db9e9c72ba.webp?x-oss-process=image/resize,p_80/format,jpg)
如果想统计 SQL 执行时间。所以对于程序而言可以得到粗略公式
▐ 添加增加 JDBC 追踪
阅读过 Hibernate 或者 MyBatis 等持久化框架的应该比较了解 Statement 位于 java.sql 基础包下
![](https://static001.geekbang.org/infoq/24/24366d7aaaf6ebce1a925608d36978f7.webp?x-oss-process=image/resize,p_80/format,jpg)
Statement 提供了用于执行静态 SQL 语句并返回它产生的结果的对象。默认情况下,每个 Statement 对象只能同时打开一个 ResultSet 对象。
因此,如果一个 ResultSet 对象的读取与另一个的读取交错,则每个对象都必须由不同的 Statement 对象生成。如果存在打开的对象,则 Statement 接口中的所有执行方法都会隐式关闭该 Statement 的当前 ResultSet 对象。
继续查看源码可以发现在 Statement 提供了用于执行方法后,PreparedStatement 预编译 SQL 语句的对象。SQL 语句被预编译并存储在 PreparedStatement 对象中。然后可以使用此对象多次有效地执行此语句。
![](https://static001.geekbang.org/infoq/80/80d9147b8fdb650b05d5a50fc1b94acb.webp?x-oss-process=image/resize,p_80/format,jpg)
为了验证这个思路,可以借鉴其他定制化数据库驱动。
![](https://static001.geekbang.org/infoq/9b/9b6ad38594994a884828211b07800071.webp?x-oss-process=image/resize,p_80/format,jpg)
定义 StatementWraper 实现 Statement 提供了用于执行静态 SQL 语句并返回它产生的结果的对象。
![](https://static001.geekbang.org/infoq/5a/5a2221726eaeb8a5a09ef761145dcf2a.webp?x-oss-process=image/resize,p_80/format,jpg)
![](https://static001.geekbang.org/infoq/19/199005b03d75ba329afea304b9a7f8c2.webp?x-oss-process=image/resize,p_80/format,jpg)
记录日志详情
![](https://static001.geekbang.org/infoq/c8/c8f82eaf86150db7b20a44da05b0ff12.webp?x-oss-process=image/resize,p_80/format,jpg)
这样就有了文章开头的程序执行过程中锁触发的 SQL 执行耗时情况。
![](https://static001.geekbang.org/infoq/bb/bbb84b643bd79167094f677dce0c6e18.webp?x-oss-process=image/resize,p_80/format,jpg)
同理定义 PreparedStatementWraper 实现 PreparedStatement
![](https://static001.geekbang.org/infoq/19/19d7a45dfcdfed401fa2c850b19d30f2.webp?x-oss-process=image/resize,p_80/format,jpg)
最后日志输出使用 logback 组件进行日志采集
对这类问题先前有做介绍