文档中心>云数据库 PostgreSQL>实践教程>通过 auto_explain 插件实现分析慢 SQL

通过 auto_explain 插件实现分析慢 SQL

最近更新时间:2024-05-27 12:30:21

我的收藏
注意:
auto_explain 的开启需要重启数据库,请您提前规划运维时间窗。
auto_explain 开启后会有一定的性能损耗,与具体的业务有关,请先充分测试。
auto_explain 开启后可能会因为产生过多的日志而导致磁盘空间的上升,请知悉。
如您需要开启 auto_explain 并下载日志,请 提交工单 联系我们。

重点参数说明

auto_explain 插件提供一种自动记录 SQL 执行计划的功能。当您在实例中开启该插件之后,可以通过设置多个参数来实现该能力。下面将针对重点的几个参数进行说明,详细说明请参考 官方文档
auto_explain.log_min_duration
该参数主要用于决定执行耗时超过多长时间的 SQL 语句会被记录执行计划。默认为 -1,代表不记录。单位为毫秒。
auto_explain.log_analyze
加此参数可以打开 explain analyze 的值。默认关闭。
auto_explain.log_timing
加此参数可以打印语句执行时间。默认关闭。
auto_explain.log_verbose
加此参数可以增加 explain 中 verbose 信息输出。默认关闭。

示例说明

假如实例中有 database a_all,该 database 的 public 模式下有10张表格,分别为:student_info_b0、student_info_b1、student_info_b2、student_info_b3、student_info_b4、student_info_b5、student_info_b6、student_info_b7、student_info_b8、student_info_b9
当前云数据库 PostgreSQL 实例已经开启了 auto_explain 插件。其参数值如下:
a_all=> show auto_explain.log_min_duration;
auto_explain.log_min_duration
-------------------------------
10ms
(1 row)

a_all=> show auto_explain.log_analyze;
auto_explain.log_analyze
--------------------------
on
(1 row)

a_all=> show auto_explain.log_verbose;
auto_explain.log_verbose
--------------------------
on
(1 row)

a_all=> show auto_explain.log_timing;
auto_explain.log_timing
-------------------------
on
(1 row)
执行如下语句:
SELECT user_id, COUNT(*) OVER (PARTITION BY user_id) as countFROM ( SELECT user_id FROM student_info_b0 UNION ALL SELECT user_id FROM student_info_b1 UNION ALL SELECT user_id FROM student_info_b2 UNION ALL SELECT user_id FROM student_info_b3 UNION ALL SELECT user_id FROM student_info_b4 UNION ALL SELECT user_id FROM student_info_b5 UNION ALL SELECT user_id FROM student_info_b6 UNION ALL SELECT user_id FROM student_info_b7 UNION ALL SELECT user_id FROM student_info_b8 UNION ALL SELECT user_id FROM student_info_b9) AS all_students;
云数据库 PostgreSQL 的控制台 看到的慢日志记录如图所示:

下载的 auto_explain 日志中执行计划如下:
duration: 147.603 ms plan:
Query Text: SELECT user_id, COUNT(*) OVER (PARTITION BY user_id) as count
FROM (
SELECT user_id FROM student_info_b0
UNION ALL
SELECT user_id FROM student_info_b1
UNION ALL
SELECT user_id FROM student_info_b2
UNION ALL
SELECT user_id FROM student_info_b3
UNION ALL
SELECT user_id FROM student_info_b4
UNION ALL
SELECT user_id FROM student_info_b5
UNION ALL
SELECT user_id FROM student_info_b6
UNION ALL
SELECT user_id FROM student_info_b7
UNION ALL
SELECT user_id FROM student_info_b8
UNION ALL
SELECT user_id FROM student_info_b9
) AS all_students;
WindowAgg (cost=19181.71..21924.66 rows=156740 width=14) (actual time=56.009..116.522 rows=157000 loops=1)
Output: student_info_b0.user_id, count(*) OVER (?)
-> Sort (cost=19181.71..19573.56 rows=156740 width=6) (actual time=55.956..72.756 rows=157000 loops=1)
Output: student_info_b0.user_id
Sort Key: student_info_b0.user_id
Sort Method: external merge Disk: 2448kB
-> Append (cost=0.00..3511.10 rows=156740 width=6) (actual time=0.010..20.861 rows=157000 loops=1)
-> Seq Scan on public.student_info_b0 (cost=0.00..272.74 rows=15674 width=4) (actual time=0.009..1.367 rows=15700 loops=1)
Output: student_info_b0.user_id
-> Seq Scan on public.student_info_b1 (cost=0.00..272.74 rows=15674 width=6) (actual time=0.005..1.302 rows=15700 loops=1)
Output: student_info_b1.user_id
-> Seq Scan on public.student_info_b2 (cost=0.00..272.74 rows=15674 width=6) (actual time=0.004..1.316 rows=15700 loops=1)
Output: student_info_b2.user_id
-> Seq Scan on public.student_info_b3 (cost=0.00..272.74 rows=15674 width=6) (actual time=0.005..1.318 rows=15700 loops=1)
Output: student_info_b3.user_id
-> Seq Scan on public.student_info_b4 (cost=0.00..272.74 rows=15674 width=6) (actual time=0.006..1.320 rows=15700 loops=1)
Output: student_info_b4.user_id
-> Seq Scan on public.student_info_b5 (cost=0.00..272.74 rows=15674 width=6) (actual time=0.005..1.294 rows=15700 loops=1)
Output: student_info_b5.user_id
-> Seq Scan on public.student_info_b6 (cost=0.00..272.74 rows=15674 width=6) (actual time=0.004..1.377 rows=15700 loops=1)
Output: student_info_b6.user_id
-> Seq Scan on public.student_info_b7 (cost=0.00..272.74 rows=15674 width=6) (actual time=0.005..1.327 rows=15700 loops=1)
Output: student_info_b7.user_id
-> Seq Scan on public.student_info_b8 (cost=0.00..272.74 rows=15674 width=6) (actual time=0.006..1.285 rows=15700 loops=1)
Output: student_info_b8.user_id
-> Seq Scan on public.student_info_b9 (cost=0.00..272.74 rows=15674 width=6) (actual time=0.004..1.293 rows=15700 loops=1)
Output: student_info_b9.user_id

如此,我们能清晰的查看该慢 SQL 的详细执行计划,并进行后续的业务分析。