如何利用日志链路追踪程序执行的慢 SQL？

导读：查看 SQL 的执行效率，不难想到使用 explain 分析慢查询，但是前提是你需要非常了解业务背景。否则很难精准定位到。

系统都是逐渐演进的，一个系统在运行中必须是根据场景逐渐地提高优化性能。高并发就是对资源的节约的考验，这种考验除了更换优秀和先进的技术，优化架构，还在于从小处出发，对尽可能节约的资源进行节约。

而在一个系统的数据访问中，系统的瓶颈往往是来自于数据库，因此我们要尽可能减少对数据库的访问！

一、背景

有没有遇到这种情况，领导突然安排一件事情：这几个接口压测指标太低需要针对性优化一下。

当然理想的情况下你对业务场景非常熟悉，可以大概定位问题来分析业务精准评估哪些 SQL 会有性能瓶颈。

然后开始百度：如何提高 SQL 执行效率？

通过 explain、show profile 和 trace 等诊断工具来分析慢查询。

但是大多数情况下业务线过长，不可能一个人完成。涉及到各种策略模式、监听动作。想直接定位到点还是需要输出请求发起后所触发的执行的 SQL 以及执行效率。这里效率单单指代 SQL 执行的时间。

目标明确后开始整活吧。

二、添加 JDBC 追踪

继续前一篇文章的话题：如何利用好日志链路追踪做性能分析？

▐ SQL 执行时间公式

要想处理此类问题首先的分析，SQL 执行时间计算如何来划分？SQL 的语句执行过程大致如下图所示。

如果想统计 SQL 执行时间。所以对于程序而言可以得到粗略公式

SQL执行时间=提取数据之后时间-语法解析开始时间

▐ 添加增加 JDBC 追踪

阅读过 Hibernate 或者 MyBatis 等持久化框架的应该比较了解 Statement 位于 java.sql 基础包下

Statement 提供了用于执行静态 SQL 语句并返回它产生的结果的对象。默认情况下，每个 Statement 对象只能同时打开一个 ResultSet 对象。

因此，如果一个 ResultSet 对象的读取与另一个的读取交错，则每个对象都必须由不同的 Statement 对象生成。如果存在打开的对象，则 Statement 接口中的所有执行方法都会隐式关闭该 Statement 的当前 ResultSet 对象。

继续查看源码可以发现在 Statement 提供了用于执行方法后，PreparedStatement 预编译 SQL 语句的对象。SQL 语句被预编译并存储在 PreparedStatement 对象中。然后可以使用此对象多次有效地执行此语句。

为了验证这个思路，可以借鉴其他定制化数据库驱动。


定义 StatementWraper 实现 Statement 提供了用于执行静态 SQL 语句并返回它产生的结果的对象。

记录日志详情

public class PreparedStatementWraper extends StatementWraper
  implements PreparedStatement {
 private PreparedStatement raw;

 private String sql;

 public PreparedStatementWraper(PreparedStatement raw, String sql) {
  super(raw);
  this.raw = raw;
  this.sql = sql;
 }

 // ========== 记录日志 ==========
 @Override
 public ResultSet executeQuery() throws SQLException {
  long startTime = System.currentTimeMillis();
  try {
   return raw.executeQuery();
  } finally {
   doLog("executeQuery", sql, startTime);
  }
 }
....
j

最后日志输出使用 logback 组件进行日志采集

对这类问题先前有做介绍

• 微服务分布式架构中，如何实现日志链路跟踪？
• 如何利用好日志链路追踪做性能分析？