记一次 SQL 优化过程,从 7.2s 到 10ms

2,273 阅读10分钟

最近在实现一个列表查询的功能时遇到了【性能】问题,由于对后端性能方面没有太深入的了解和实践,所以在发现问题后卡了较长时间,通过查阅文档,借助分析工具,最终找到并解决问题。

这篇文章记录我解决问题的过程和学习到的新知识,如果有理解错误的地方,请帮我指出。

执行环境:Postgres 9.6.0Sequelize 4.44.0

问题背景

我要实现的功能是提供一个后端列表查询接口,这个接口涉及到数据库的三个表,分别是 UserSurveys, Surveys, Questionnaires。实体关系是 1:1:1

查询接口从 User_Surveys 开始,通过外键 survey_id 关联 Surveys 表,外键 quesitonnaire_id 关联 Questionnaires 表。

这个接口需要支持根据 Questionnaire.name 过滤最终返回的 UserSurveys 条目。很简单的需求,之前已经做过很多次,我不加思索地写下以下代码并迅速提交代码(隐去了不相关的代码逻辑),项目中使用 Sequelize (一个 Node.js ORM 库)。

await UserSurvey.findAndCountAll({
  offset,
  limit,
  where: {
    status,
  },
  include: [
    {
      model: Survey,
      required: true,
      include: [
        {
          model: Questionnaire,
          required: true,
          where: {
              name: {
                [Op.like]: `%${questoinnaire_name}%`
              }
          }
          }
        }
      ]
    }
  ],
  order: [
    ['created_at', 'DESC'],
  ]
});

发完测试环境,开发自测的过程中发现,当我传入 querstionnaire_name 的时候请求特别慢!

慢到什么程度?搜索【问卷】请求完成时间是 【14.89s】!!!简单刷新重试几次,确认问题来自后端接口。

顺着请求路由,回溯到后端代码,确认我编写的代码没有问题。那就是 SQL 执行的问题?在日志文件中找到最终执行的 SQL 语句。

EXPLAIN ANALYZE SELECT "survey->questionnaire"."id"
  AS "survey.questionnaire.id", "survey->questionnaire"."name" AS "survey.questionnaire.name" FROM ("user_surveys" AS "user_survey"
INNER JOIN "surveys" AS "survey" ON "user_survey"."survey_id" = "survey"."id"
INNER JOIN "questionnaires" AS "survey->questionnaire" ON "survey"."questionnaire_id" = "survey->questionnaire"."id"
  AND  "survey->questionnaire"."name" like '%问卷%') where "user_survey".status = 'PUBLISH' ORDER BY"user_survey"."created_at" DESC LIMIT 10 OFFSET 0;

三个表通过条件 Inner JoinSequelize 生成的 SQL 没什么问题,怎么确认是 SQL 执行语句的问题呢?

EXPLAIN 命令

Postgres 执行 SQL 语句之前,会对查询条件,数据属性,表结构等进行分析,选出一种最优的 Query Plan。在 Query Plan 中描述了 Postgres 将会使用何种方式扫描数据库,如何连接表,运行成本等等信息。

通过阅读理解这些信息,开发者就能更好地理解查询语句的运行过程。

使用 EXPLAIN 命令很简单,只需要在原有语句前添加 EXPLAIN。例如官方文档中的例子。

EXPLAIN SELECT * FROM tenk1;

                         QUERY PLAN
-------------------------------------------------------------
 Seq Scan on tenk1  (cost=0.00..458.00 rows=10000 width=244)

执行 EXPLAIN SELECT * FROM tenk1; 得到的运行结果 Postgres 给出的 QUERY PLAN,结果中可以看到将会使用 Seq Scan 的方式,遍历 tenk1 表,cost=0.00..458.0 表示预计的启动开销 0.00, 和返回所有记录的总开销458.00,总共会返回 10000 行(rows),每行占用内存 244 bytes

EXPLAIN 命令给出的是预估的执行计划数据,并不会真正地运行语句,想得到更真实的运行数据,需要使用加上 ANALYZE 参数。

EXPLAIN ANALYZE SELECT * FROM tenk1;

                                        QUERY PLAN
--------------------------------------------------------------------------------------------------------
 Seq Scan on tenk1  (cost=0.00..458.00 rows=10000 width=244) (actual time=0.128..0.377 rows=10000 loops=1)
 Planning time: 0.181 ms
 Execution time: 0.501 ms

加上 ANALYZE 参数之后,可以看到操作被执行的总次数(loops),而 actual timerows 是每次执行的平均值,以及整个语句最终执行时长(Execution time)。

"cost" 使用的是任意单位,通常是关心其相对值。而"actual time"数值是以真实时间的毫秒计的。

使用ANALYZE如果需要执行 UPDATEINSERTDELETE 等操作要留心,最好是在事务中执行。

BEGIN;
EXPLAIN ANALYZE UPDATE ...;
ROLLBACK; or COMMIT;

阅读 Query Plan

Query Plan 返回的是一个树结构,执行顺序是子节点优先,一个上层节点的开销包括它的所有子节点的开销。

举个例子:

EXPLAIN ANALYZE SELECT *
FROM tenk1 t1, tenk2 t2
WHERE t1.unique1 < 100 AND t1.unique2 = t2.unique2
ORDER BY t1.fivethous;

返回的 Query Plan

--------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=717.34..717.59 rows=101 width=488) (actual time=7.761..7.774 rows=100 loops=1)
   Sort Key: t1.fivethous
   Sort Method: quicksort  Memory: 77kB
   ->  Hash Join  (cost=230.47..713.98 rows=101 width=488) (actual time=0.711..7.427 rows=100 loops=1)
         Hash Cond: (t2.unique2 = t1.unique2)
         ->  Seq Scan on tenk2 t2  (cost=0.00..445.00 rows=10000 width=244) (actual time=0.007..2.583 rows=10000 loops=1)
         ->  Hash  (cost=229.20..229.20 rows=101 width=244) (actual time=0.659..0.659 rows=100 loops=1)
               Buckets: 1024  Batches: 1  Memory Usage: 28kB
               ->  Bitmap Heap Scan on tenk1 t1  (cost=5.07..229.20 rows=101 width=244) (actual time=0.080..0.526 rows=100 loops=1)
                     Recheck Cond: (unique1 < 100)
                     ->  Bitmap Index Scan on tenk1_unique1  (cost=0.00..5.04 rows=101 width=0) (actual time=0.049..0.049 rows=100 loops=1)
                           Index Cond: (unique1 < 100)
 Planning time: 0.194 ms
 Execution time: 8.008 ms

-> 标记着树节点,暂时移除开销的信息,抽离出来树干结构如下。

Sort
Sort Key: t1.fivethous
Sort Method: quicksort  Memory: 77kB
└── Hash Join
    Hash Cond: (t2.unique2 = t1.unique2)
    ├── Seq Scan
    └── Hash
        └── Bitmap Heap Scan
            └── Bitmap Index Scan
                  Index Cond: (unique1 < 100)

从这个结构中可以看出,Postgres 使用 Seq Scan 的方式读取 tenk2 表,再使用 Bitmap Heap ScanBitmap Index Scan 的方式扫描 tenk1 表,将符合条件(unique1 < 100)的条目读入内存 Hash。

接着使用 Hash Join 的连接方式,根据连接条件Hash Cond: (t2.unique2 = t1.unique2)连接子节点的扫描结果。

最后使用 quicksort 的方式,基于 t1.fivethous 字段进行排序,得到最终查询结果。

什么是索引(Index)?

数据库中索引就像书籍中的关键字检索,按字符顺序排列,当我们想看某个关键字在书本中出现的位置的时候,可以通过这份 Index 快速定位到具体页面,直接翻到对应的页面,而不是从第一页开始一页一页地查找关键字。

数据库中分为 ClusterIndex 和 NonClusterIndex,ClusterIndex 一个表只有一个,由数据库根据 Table 唯一主键创建,NonClusterIndex 一个表可以出现很多个,可以由用户自由维护。

当我们在 DB 中运行 Create Index 时,就是创建了一个 NonClusterIndex,数据库会维护一个结构来记录 ClusterIndex 和 NonClusterIndex 的关系。

按照 NonClusterIndex 进行排序,之后使用索引就能快速定位到想要查找的条目。

不过需要注意:

  1. 维护索引本身需要成本的,在数据库内容发生变更时,通常都需要对应地调整索引。
  2. 使用索引也需要开销,使用索引的顺序会导致数据库读取头在行间跳跃,这比顺序读取的开销要大得多。

Seq Scan、Index Scan、Bitmap Heap Scan

在执行不同的 Query 时,规划器可能会使用不同的扫描节点方式。

EXPLAIN SELECT * FROM tenk1 WHERE unique1 < 7000;

                         QUERY PLAN
------------------------------------------------------------
 Seq Scan on tenk1  (cost=0.00..483.00 rows=7001 width=244)
   Filter: (unique1 < 7000)

上面的例子中,规划器将使用 Seq Scan 的方式扫描 tenk1 表的每一行,根据 Filter 条件过滤符合条件的条目。

有的时候,规划器则会选择使用 Index Scan,通过索引条件直接查找。

EXPLAIN SELECT * FROM tenk1 WHERE unique1 = 42;

                                 QUERY PLAN
-----------------------------------------------------------------------------
 Index Scan using tenk1_unique1 on tenk1  (cost=0.29..8.30 rows=1 width=244)
   Index Cond: (unique1 = 42)

在这种规划类型中,表的数据行是以索引顺序抓取的,意味着数据库读取头需要在数据行之前来回跳动,数据量很大的情况下,开销非常大。

还有另一种类型 Bitmap Heap Scan

EXPLAIN SELECT * FROM tenk1 WHERE unique1 < 100 AND stringu1 = 'xxx';

                                  QUERY PLAN
------------------------------------------------------------------------------
 Bitmap Heap Scan on tenk1  (cost=5.04..229.43 rows=1 width=244)
   Recheck Cond: (unique1 < 100)
   Filter: (stringu1 = 'xxx'::name)
   ->  Bitmap Index Scan on tenk1_unique1  (cost=0.00..5.04 rows=101 width=0)
         Index Cond: (unique1 < 100)

Bitmap Heap Scan 分为两步,首先通过 Bitmap Index Scan 从表中抓取出匹配的行,再由上层规划节点在读取他们之前按照物理位置排序,这样可以最小化开销。

接着看表连接相关的知识。

Nested loops, Hash Join, Merge Join

Nested loops 工作方式是循环从一张表中读取数据,然后访问另一张表(通常有索引)。驱动表中的每一行与 inner 表中的相应记录JOIN,类似一个嵌套的循环。

EXPLAIN SELECT *
FROM tenk1 t1, tenk2 t2
WHERE t1.unique1 < 10 AND t1.unique2 = t2.unique2;

                                      QUERY PLAN
--------------------------------------------------------------------------------------
 Nested Loop  (cost=4.65..118.62 rows=10 width=488)
   ->  Bitmap Heap Scan on tenk1 t1  (cost=4.36..39.47 rows=10 width=244)
         Recheck Cond: (unique1 < 10)
         ->  Bitmap Index Scan on tenk1_unique1  (cost=0.00..4.36 rows=10 width=0)
               Index Cond: (unique1 < 10)
   ->  Index Scan using tenk2_unique2 on tenk2 t2  (cost=0.29..7.91 rows=1 width=244)
         Index Cond: (unique2 = t1.unique2)

在这个例子中,规划器使用了 Nested Loop 的表连接方式,使用 Bitmap Heap Scan 扫描 tenk1 表,获得 10 行数据。接着 Nested Loop 将对获得的每行数据进行执行一次内部扫描,将匹配条件的 (unique2 = t1.unique2) 数据连接。运行成本约为 【外层扫描开销 39.27】 + 【内层扫描开销 10 * 7.91】+ 一点 CPU 的计算时间。

使用 JS 代码描述,过程大概如下,对于 tenk1 中的每一行数据,都会在 tenk2 中执行一次查找,如果没有索引的情况下,时间复杂度是 O(MN)。

for (const t1 of tenk1) {
  for (const t2 of tenk2) {
    if (t1.unique2 === t2.unique2) {
      t1.tenk2 = t2;
      break;
    }
  }
}

稍加修改查询条件,可能会得到另一种连接方式

EXPLAIN SELECT *
FROM tenk1 t1, tenk2 t2
WHERE t1.unique1 < 100 AND t1.unique2 = t2.unique2;

                                        QUERY PLAN
------------------------------------------------------------------------------------------
 Hash Join  (cost=230.47..713.98 rows=101 width=488)
   Hash Cond: (t2.unique2 = t1.unique2)
   ->  Seq Scan on tenk2 t2  (cost=0.00..445.00 rows=10000 width=244)
   ->  Hash  (cost=229.20..229.20 rows=101 width=244)
         ->  Bitmap Heap Scan on tenk1 t1  (cost=5.07..229.20 rows=101 width=244)
               Recheck Cond: (unique1 < 100)
               ->  Bitmap Index Scan on tenk1_unique1  (cost=0.00..5.04 rows=101 width=0)
                     Index Cond: (unique1 < 100)

在这个例子中,规划器选择了哈希连接,tenk1 (通常是选择较小的表) 通过 Bitmap Heap Scan 扫入到内存中的哈希表,结合 tenk2 的扫描结果对每一行进行哈希表探测。

用 JS 代码描述代码执行过程大致如下,这种方式的时间复杂度为 O(N + M)

const dict = {};
for (const t1 of tenk1) {
  dict[t1.unique2] = t1;
}

for (const t2 of tenk2) {
  t2['tenk2'] = dict[t2.unique2]
}

还有一种连接方式 Merge Join ,这种连接方式要求输入中的连接键都是有序的。

EXPLAIN SELECT *
FROM tenk1 t1, onek t2
WHERE t1.unique1 < 100 AND t1.unique2 = t2.unique2;

                                        QUERY PLAN
------------------------------------------------------------------------------------------
 Merge Join  (cost=198.11..268.19 rows=10 width=488)
   Merge Cond: (t1.unique2 = t2.unique2)
   ->  Index Scan using tenk1_unique2 on tenk1 t1  (cost=0.29..656.28 rows=101 width=244)
         Filter: (unique1 < 100)
   ->  Sort  (cost=197.83..200.33 rows=1000 width=244)
         Sort Key: t2.unique2
         ->  Seq Scan on onek t2  (cost=0.00..148.00 rows=1000 width=244)

对于大量行的排序,顺序扫描加排序通常比索引扫描更高效,因为索引扫描需要非连续的磁盘访问。

定位问题

掌握了如何使用 EXPLAIN 命令,回到最初的问题,查看为什么我的查询语句问题出在哪里?

                                                                             QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=256.52..256.52 rows=1 width=540) (actual time=7257.566..7257.568 rows=10 loops=1)
   ->  Sort  (cost=256.52..256.52 rows=1 width=540) (actual time=7257.564..7257.566 rows=10 loops=1)
         Sort Key: user_survey.created_at DESC
         Sort Method: top-N heapsort  Memory: 26kB
         ->  Nested Loop  (cost=26.88..256.51 rows=1 width=540) (actual time=156.527..7257.419 rows=196 loops=1)
               ->  Nested Loop  (cost=0.00..221.74 rows=1 width=548) (actual time=0.957..7057.564 rows=1647 loops=1)
                     Join Filter: (survey.questionnaire_id = "survey->questionnaire".id)
                     Rows Removed by Join Filter: 6539694
                     ->  Seq Scan on questionnaires "survey->questionnaire"  (cost=0.00..130.07 rows=1 width=532) (actual time=0.009..1.591 rows=3441 loops=1)
                           Filter: ((name)::text ~~ '%问卷%'::text)
                           Rows Removed by Filter: 176
                     ->  Seq Scan on surveys survey  (cost=0.00..67.96 rows=1896 width=32) (actual time=0.001..1.247 rows=1901 loops=3441)
               ->  Bitmap Heap Scan on user_surveys user_survey  (cost=26.88..34.75 rows=2 width=24) (actual time=0.121..0.121 rows=0 loops=1647)
                     Recheck Cond: (((status)::text = 'PUBLISH'::text) AND (survey_id = survey.id))
                     Heap Blocks: exact=134
                     ->  BitmapAnd  (cost=26.88..26.88 rows=2 width=0) (actual time=0.120..0.120 rows=0 loops=1647)
                           ->  Bitmap Index Scan on user_surveys_status_index  (cost=0.00..10.23 rows=242 width=0) (actual time=0.064..0.064 rows=310 loops=1647)
                                 Index Cond: ((status)::text = 'PUBLISH'::text)
                           ->  Bitmap Index Scan on user_surveys_survey_id_index  (cost=0.00..16.33 rows=1753 width=0) (actual time=0.055..0.055 rows=72 loops=1647)
                                 Index Cond: (survey_id = survey.id)
 Planning time: 1.434 ms
 Execution time: 7257.672 ms
(22 rows)

从 Query Plan 上可以看到,这个查询需要 7.2s 的执行时间!哪里有问题?

Nested Loop  (cost=0.00..221.74 rows=1 width=548) (actual time=0.957..7057.564 rows=1647 loops=1)
   Join Filter: (survey.questionnaire_id = "survey->questionnaire".id)
   Rows Removed by Join Filter: 6539694
   ->  Seq Scan on questionnaires "survey->questionnaire"  (cost=0.00..130.07 rows=1 width=532) (actual time=0.009..1.591 rows=3441 loops=1)
         Filter: ((name)::text ~~ '%问卷%'::text)
         Rows Removed by Filter: 176
   ->  Seq Scan on surveys survey  (cost=0.00..67.96 rows=1896 width=32) (actual time=0.001..1.247 rows=1901 loops=3441)

从报告中可以看出,规划器在连接 Surveys 和 Questionnaires 表时,使用的连接方式是 Nested Loop,外层遍历 Questionnaires 表得到 3441 行数据,内层继续顺序遍历 Surveys 表,执行 3441 次,前面提到了,这种方式最差的时间复杂度是 O(MN)。

对症下药,优化的方案就是让规划器有更优的执行方案可选,改善表连接的糟糕表现,具体操作是给 surveys.questionnaire_id 添加索引。

CREATE INDEX surveys_questionnaire_id_index ON surveys (questionnaire_id);

再次执行 EXPLAIN ANYLYZE,可以看到规划器使用上了我们增加的索引,基于索引检索之后再进行表连接明显快了很多,查询总时长从 7.2s 减小到 160ms

...
Nested Loop  (cost=4.34..156.90 rows=1 width=548) (actual time=0.030..7.091 rows=1647 loops=1)
   ->  Seq Scan on questionnaires "survey->questionnaire"  (cost=0.00..130.07 rows=1 width=532) (actual time=0.008..0.839 rows=3441 loops=1)
         Filter: ((name)::text ~~ '%问卷%'::text)
         Rows Removed by Filter: 176
   ->  Bitmap Heap Scan on surveys survey  (cost=4.34..26.74 rows=8 width=32) (actual time=0.001..0.001 rows=0 loops=3441)
         Recheck Cond: (questionnaire_id = "survey->questionnaire".id)
         Heap Blocks: exact=281
         ->  Bitmap Index Scan on surveys_questionnaire_id_index  (cost=0.00..4.34 rows=8 width=0) (actual time=0.001..0.001 rows=0 loops=3441)
               Index Cond: (questionnaire_id = "survey->questionnaire".id)

 ...
 Planning time: 0.692 ms
 Execution time: 160.381 ms

继续查看报告,发现在做第外层 Nested Loop 表连接的时候,Bitmap Heap Scan on user_surveys 执行时间为 1647 * 0.085ms

Nested Loop  (cost=31.20..191.79 rows=1 width=540) (actual time=0.971..148.585 rows=196 loops=1)
   ->  Nested Loop  (cost=4.34..157.03 rows=1 width=548) (actual time=0.024..6.963 rows=1647 loops=1)
         ...
   ->  Bitmap Heap Scan on user_surveys user_survey  (cost=26.86..34.74 rows=2 width=24) (actual time=0.085..0.085 rows=0 loops=1647)
         Recheck Cond: (((status)::text = 'PUBLISH'::text) AND (survey_id = survey.id))
         Heap Blocks: exact=134
         ->  BitmapAnd  (cost=26.86..26.86 rows=2 width=0) (actual time=0.085..0.085 rows=0 loops=1647)
               ->  Bitmap Index Scan on user_surveys_status_index  (actual time=0.015..0.015 rows=310 loops=1647)
                     Index Cond: ((status)::text = 'PUBLISH'::text)
               ->  Bitmap Index Scan on user_surveys_survey_id_index  (actual time=0.069..0.069 rows=72 loops=1647)
                     Index Cond: (survey_id = survey.id)

主要时间是花在了扫描两个索引上,单次耗时 0.085ms

BitmapAnd  (cost=26.86..26.86 rows=2 width=0) (actual time=0.085..0.085 rows=0 loops=1647)
   ->  Bitmap Index Scan on user_surveys_status_index  (actual time=0.015..0.015 rows=310 loops=1647)
         Index Cond: ((status)::text = 'PUBLISH'::text)
   ->  Bitmap Index Scan on user_surveys_survey_id_index  (actual time=0.069..0.069 rows=72 loops=1647)
         Index Cond: (survey_id = survey.id)

再次对症下药,添加一个多列索引

CREATE INDEX user_surveys_status_survey_id_index ON user_surveys (status, survey_id);

多列索引列的顺序是有讲究的,按照常用频率从左到右,这样能更好地利用索引。

再次执行 EXPLAIN

Limit  (cost=163.81..163.82 rows=1 width=540) (actual time=10.097..10.099 rows=10 loops=1)
   ->  Sort  (cost=163.81..163.82 rows=1 width=540) (actual time=10.096..10.096 rows=10 loops=1)
         Sort Key: user_survey.created_at DESC
         Sort Method: top-N heapsort  Memory: 26kB
         ->  Nested Loop  (cost=4.76..163.80 rows=1 width=540) (actual time=0.258..10.023 rows=196 loops=1)
               ->  Nested Loop  (cost=4.34..157.03 rows=1 width=548) (actual time=0.027..6.812 rows=1647 loops=1)
                     ->  Seq Scan on questionnaires "survey->questionnaire"  (cost=0.00..130.21 rows=1 width=532) (actual time=0.008..0.810 rows=3441 loops=1)
                           Filter: ((name)::text ~~ '%问卷%'::text)
                           Rows Removed by Filter: 176
                     ->  Bitmap Heap Scan on surveys survey  (cost=4.34..26.74 rows=8 width=32) (actual time=0.001..0.001 rows=0 loops=3441)
                           Recheck Cond: (questionnaire_id = "survey->questionnaire".id)
                           Heap Blocks: exact=281
                           ->  Bitmap Index Scan on surveys_questionnaire_id_index  (cost=0.00..4.34 rows=8 width=0) (actual time=0.001..0.001 rows=0 loops=3441)
                                 Index Cond: (questionnaire_id = "survey->questionnaire".id)
               ->  Index Scan using user_surveys_status_survey_id_index on user_surveys user_survey  (cost=0.42..6.75 rows=2 width=24) (actual time=0.002..0.002 rows=0 loops=1647)
                     Index Cond: (((status)::text = 'PUBLISH'::text) AND (survey_id = survey.id))
 Planning time: 0.622 ms
 Execution time: 10.163 ms

现在执行时长已经降到了 10ms 了,10ms 是规划器执行的时间,加上数据传递给客户端,ORM 包的处理,网络传输等时间才更接近用户在前端最终感知到的时间。

最终,Chrome Network Panel 上看,从前端发起查询时长终于降到合理的范围(前端 Input 组件本身会做 500ms Debounce)。

总结

通过一次完整的学习,掌握了科学有效的方法,以后就不用盲目去猜测是否需要添加索引。遇到性能问题也能更快更有效地解决。

再次说明,这篇文章是我在学习过程中的笔记,由于水平有限,可能存在不准确的信息,仅供参考。深入的学习,还请以官方文档为准。

推荐阅读