码农架构 | 如何优化日志链路追踪输出 SQL 的执行效率?

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

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

一、背景


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

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

然后开始百度:如何提高 SQL 执行效率?

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

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

目标明确后开始整活吧。

二、添加 JDBC 追踪


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

image

▐ SQL 执行时间公式

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

image

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

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

复制代码

▐ 添加增加 JDBC 追踪

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

image

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

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

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

image

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

image

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

image
image

记录日志详情

image
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 执行耗时情况。

image

同理定义 PreparedStatementWraper 实现 PreparedStatement

image
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 组件进行日志采集

对这类问题先前有做介绍

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 212,080评论 6 493
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 90,422评论 3 385
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 157,630评论 0 348
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 56,554评论 1 284
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 65,662评论 6 386
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 49,856评论 1 290
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,014评论 3 408
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 37,752评论 0 268
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,212评论 1 303
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,541评论 2 327
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,687评论 1 341
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,347评论 4 331
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,973评论 3 315
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,777评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,006评论 1 266
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 46,406评论 2 360
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 43,576评论 2 349

推荐阅读更多精彩内容