通过 auto_explain 插件实现分析慢 SQL

Recent Pages

通过 auto_explain 插件实现分析慢 SQL

最后更新时间：2024-08-09 15:21:07

注意：
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 的详细执行计划，并进行后续的业务分析。