微服务架构 | 如何优化日志链路追踪输出 SQL 的执行效率？

作者：码农架构

2021 年 12 月 16 日
本文字数：1749 字
阅读完需：约 6 分钟

导读：查看 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 组件进行日志采集

对这类问题先前有做介绍

发布于: 5 小时前阅读数: 13

原文链接:【http://xie.infoq.cn/article/1e022fafd4cf0d0a50486fb37】。文章转载请联系作者。

码农架构

关注

公众号：码农架构 2018.03.22 加入

专注于系统架构、高可用、高性能、高并发类技术分享

发布

暂无评论

创作场景

微服务架构 | 如何优化日志链路追踪输出 SQL 的执行效率？

一、背景

二、添加 JDBC 追踪

▐ SQL 执行时间公式

▐ 添加增加 JDBC 追踪

码农架构

评论