Infrastructure at your Service

Daniel Westermann

PostgreSQL 12: Explain will display custom settings, if instructed

How many times did you try to solve a performance issue but have not been able to reproduce the explain plan? Whatever you tried you always got a different result. Lets say you managed to get a dump of the database in question, got all the PostreSQL parameters the same, gathered statistics but still you do not manage to get the same plan as the one who reported the issue. What could be a potential issue here? Lets do a short demo:

Imagine someone is sending you this plan for a simple count(*) against pg_class:

postgres=# explain (analyze) select count(*) from pg_class;
                                                                 QUERY PLAN                                                                  
---------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=23.10..23.11 rows=1 width=8) (actual time=0.293..0.293 rows=1 loops=1)
   ->  Index Only Scan using pg_class_oid_index on pg_class  (cost=0.27..22.12 rows=390 width=0) (actual time=0.103..0.214 rows=390 loops=1)
         Heap Fetches: 0
 Planning Time: 0.155 ms
 Execution Time: 0.384 ms
(5 rows)

When you try the same on your environment the plan always looks like this (sequential scan, but not an index only scan):

postgres=# explain (analyze) select count(*) from pg_class;
                                                 QUERY PLAN                                                  
-------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=17.88..17.89 rows=1 width=8) (actual time=0.322..0.323 rows=1 loops=1)
   ->  Seq Scan on pg_class  (cost=0.00..16.90 rows=390 width=0) (actual time=0.017..0.220 rows=390 loops=1)
 Planning Time: 1.623 ms
 Execution Time: 0.688 ms
(4 rows)

In this case the index only scan is even faster, but usually you get a sequential scan because costs are lower. Whatever you try, you can not reproduce it. What you can’t know: The person reporting the issue didn’t tell you about that:

postgres=# set enable_seqscan = off;
SET
postgres=# explain (analyze) select count(*) from pg_class;
                                                                 QUERY PLAN                                                                  
---------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=23.10..23.11 rows=1 width=8) (actual time=0.230..0.230 rows=1 loops=1)
   ->  Index Only Scan using pg_class_oid_index on pg_class  (cost=0.27..22.12 rows=390 width=0) (actual time=0.032..0.147 rows=390 loops=1)
         Heap Fetches: 0
 Planning Time: 0.130 ms
 Execution Time: 0.281 ms

Just before executing the statement a parameter has been changed which influences PostgreSQL’s choise about the best plan. And this is where the new feature of PostgreSQL 12 becomes handy:

postgres=# explain (analyze,settings) select count(*) from pg_class;
                                                                 QUERY PLAN                                                                  
---------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=23.10..23.11 rows=1 width=8) (actual time=0.309..0.310 rows=1 loops=1)
   ->  Index Only Scan using pg_class_oid_index on pg_class  (cost=0.27..22.12 rows=390 width=0) (actual time=0.045..0.202 rows=390 loops=1)
         Heap Fetches: 0
 Settings: enable_seqscan = 'off'
 Planning Time: 0.198 ms
 Execution Time: 0.395 ms
(6 rows)

postgres=# 

From PostgreSQL 12 on you can ask explain to display any setting that has been changed and influenced the decision on which plan to choose. This might be optimizer parameters as here, but this might also be others when they differ from the global setting:

postgres=# explain (analyze,settings) select count(*) from pg_class;
                                                 QUERY PLAN                                                  
-------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=17.88..17.89 rows=1 width=8) (actual time=0.197..0.198 rows=1 loops=1)
   ->  Seq Scan on pg_class  (cost=0.00..16.90 rows=390 width=0) (actual time=0.016..0.121 rows=390 loops=1)
 Settings: work_mem = '64MB'
Planning Time: 0.162 ms
 Execution Time: 0.418 ms
(5 rows)

… or:

postgres=# set from_collapse_limit = 13;
SET
postgres=# explain (analyze,settings) select count(*) from pg_class;
                                                 QUERY PLAN                                                  
-------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=17.88..17.89 rows=1 width=8) (actual time=0.190..0.190 rows=1 loops=1)
   ->  Seq Scan on pg_class  (cost=0.00..16.90 rows=390 width=0) (actual time=0.012..0.115 rows=390 loops=1)
 Settings: from_collapse_limit = '13', work_mem = '64MB'
 Planning Time: 0.185 ms
 Execution Time: 0.263 ms
(5 rows)

Nice addition. Asking people to use the “settings” switch with analyze, you can be sure on what was changed from the global settings so it is much easier to reproduce the issue and to see what’s going on.

Parameters that do not influence the plan do not pop up:

postgres=# set log_statement='all';
SET
postgres=# explain (analyze,settings) select count(*) from pg_class;
                                                 QUERY PLAN                                                  
-------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=17.88..17.89 rows=1 width=8) (actual time=0.199..0.200 rows=1 loops=1)
   ->  Seq Scan on pg_class  (cost=0.00..16.90 rows=390 width=0) (actual time=0.018..0.124 rows=390 loops=1)
 Settings: from_collapse_limit = '13', work_mem = '64MB'
 Planning Time: 0.161 ms
 Execution Time: 0.391 ms
(5 rows)

Leave a Reply

This site uses Akismet to reduce spam. Learn how your comment data is processed.

Daniel Westermann
Daniel Westermann

Principal Consultant & Technology Leader Open Infrastructure