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

码农架构 • 2023-01-02 • 云技术社区 • 505 阅读

导读：查看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 StatementWraper implements Statement {
    private Statement raw;

    public StatementWraper(Statement raw) {
        super();
        this.raw = raw;
    }

    /**
     * 记录日志
     */
    protected void doLog(String opt, String sql, long startTime) {
        if (sql != null) {
            sql = sql.replaceAll("\\\\s+", " ");
        }
        TraceUtil.log(StringHelper.join(
        "dt：", System.currentTimeMillis() - startTime, 
        "，TRACE-JDBC：", opt, 
        "，SQL：",sql));
    }

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

这样就有了文章开头的程序执行过程中锁触发的SQL执行耗时情况。

同理定义PreparedStatementWraper实现PreparedStatement

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);
  }
 }
....