Analyzing Slow SQL Using the auto_explain Plugin

Recent Pages

Analyzing Slow SQL Using the auto_explain Plugin

Last updated: 2024-08-09 15:21:37
Note:
Enabling auto_explain requires restarting the database. Plan the operation and maintenance time window in advance.
Enabling auto_explain will incur a certain performance loss, which is related to the specific service. Test thoroughly beforehand.
Enabling auto_explain may result in more occupied disk space due to the generation of excessive logs. Be aware of this.
If you need to enable auto_explain and download logs, submit a ticket to contact us.
Description of Key Parameters
The auto_explain plugin provides a feature for automatically recording SQL execution plans. After enabling this plugin in your instance, you can achieve this capability by setting several parameters. Some key parameters are described below. For a detailed description, refer to the official document.
auto_explain.log_min_duration
This parameter is mainly used to determine the execution duration threshold for SQL statements beyond which their execution plan will be recorded. The default value is -1, meaning no statement will be recorded. The unit is milliseconds.
auto_explain.log_analyze
This parameter can be added to enable the explain analyze value. It is disabled by default.
auto_explain.log_timing
This parameter can be added to print the statement execution time. It is disabled by default.
auto_explain.log_verbose
This parameter can be added to increase verbose information output in explain. It is disabled by default.
Examples
Assume the instance has a database named a_all, and this database has 10 tables under the public schema, namely: 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
The current TencentDB for PostgreSQL instance has enabled the auto_explain plugin. Its parameter values are as follows:
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)
The following statements are executed:
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;
The slow logs recorded on the TencentDB for PostgreSQL console are shown below:
﻿
﻿
﻿
﻿
The execution plan in the downloaded auto_explain logs are as follows:
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
﻿
Thus, we can clearly view the detailed execution plan for the slow SQL and conduct subsequent service analysis.
﻿