网络知识 娱乐 如何利用日志链路追踪程序执行的慢SQL?

如何利用日志链路追踪程序执行的慢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 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);
  }
 }
....

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

对这类问题先前有做介绍

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