云数据库 PostgreSQL 通过 auto_explain 插件实现慢 SQL 分析

auto_explain 插件提供一种自动记录 SQL 执行计划的功能。当你在实例中开启该插件之后,可以通过在 控制台 的参数设置中,进行详细能力的配置。下面将针对重点的几个参数进行说明,详细说明请参考 产品文档。

相关产品
云数据库 PostgreSQL 产品页,含版本规格、价格与购买入口。

一、重点参数说明

·auto_explain.log_min_duration

该参数主要用于决定执行耗时超过多长时间的 SQL 语句会被记录执行计划。默认为-1,代表不记录。自定义范围500-60000 ,单位为毫秒。

·auto_explain.log_analyze

加此参数可以打印执行计划的实际执行时间。默认 off ,关闭状态。

·auto_explain.log_timing

加此参数可以打印语句执行时间。默认 off ,关闭状态。

·auto_explain.log_verbose

加此参数可以增加 explain 中 verbose 信息输出,获得更详细的执行计划信息。默认 off ,关闭状态。

二、示例说明

假如实例中有 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 ——————————- 800ms(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 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;

在 云数据库 PostgreSQL 的控制台 看到的慢日志记录如下:

下载的 auto_explain 日志中执行计划如下:

duration: 147.603 ms plan:Query Text: 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;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 的详细执行计划,并进行后续的业务分析。

赞 (0)
上一篇 4天前
下一篇 4天前