Postgres Pro
Downloads
Home   >   mailing lists

Slow planning time when public schema included (12 vs. 9.4) - Mailing list pgsql-performance

From Anders Steinlein
Subject Slow planning time when public schema included (12 vs. 9.4)
Date
Msg-id CAC35HN=tS6zDy0FcQ-mPjsZ9eO_37fe9m3mLDQ+zWZWrqEB9rw@mail.gmail.com
Whole thread Raw
Responses Re: Slow planning time when public schema included (12 vs. 9.4)  (Andreas Kretschmer <andreas@a-kretschmer.de>)
Re: Slow planning time when public schema included (12 vs. 9.4)  (Tom Lane <tgl@sss.pgh.pa.us>)
List pgsql-performance
Tree view
Hi,

We have a multi-tenant app where each tenant has their own schemas, and inherits tables from tables defined in the public schema. Other shared data such as data types are also stored in the public schema. While running this app, every transaction is started with setting the search_path to <tenant_id>, public. 

We haven't noticed any issues with this before now, until we started seeing really slow planning time on some relatively simple queries:

mm_prod=> explain analyze select cs.* from contacts_segments cs inner join segments s on s.sid = cs.segment_id inner join contacts_lists cl on cl.email = cs.email and cl.lid = s.lid where cs.segment_id = 34983 and cl.lstatus = 'a';
                                                                             QUERY PLAN                                                                            
--------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Hash Join  (cost=452.96..1887.72 rows=1518 width=41) (actual time=6.581..18.845 rows=2945 loops=1)
   Hash Cond: ((cs.email)::citext = (cl.email)::citext)
   ->  Bitmap Heap Scan on contacts_segments cs  (cost=127.17..1488.89 rows=9258 width=41) (actual time=0.501..4.085 rows=9258 loops=1)
         Recheck Cond: (segment_id = 34983)
         Heap Blocks: exact=1246
         ->  Bitmap Index Scan on contacts_segments_segment_id_idx  (cost=0.00..124.86 rows=9258 width=0) (actual time=0.380..0.380 rows=9258 loops=1)
               Index Cond: (segment_id = 34983)
   ->  Hash  (cost=298.45..298.45 rows=2187 width=25) (actual time=6.061..6.061 rows=4645 loops=1)
         Buckets: 8192 (originally 4096)  Batches: 1 (originally 1)  Memory Usage: 324kB
         ->  Nested Loop  (cost=0.56..298.45 rows=2187 width=25) (actual time=0.025..3.182 rows=4645 loops=1)
               ->  Index Scan using segments_pkey on segments s  (cost=0.27..2.49 rows=1 width=8) (actual time=0.010..0.010 rows=1 loops=1)
                     Index Cond: (sid = 34983)
               ->  Index Scan using contacts_lists_lid_idx on contacts_lists cl  (cost=0.29..288.53 rows=744 width=25) (actual time=0.012..2.791 rows=4645 loops=1)
                     Index Cond: (lid = s.lid)
                     Filter: ((lstatus)::bpchar = 'a'::bpchar)
                     Rows Removed by Filter: 6628
 Planning Time: 1930.901 ms
 Execution Time: 18.996 ms
(18 rows)

The planning time is the same even if running the same query multiple times within the same session. When having only the tenant's schema in the search_path, planning time is much improved:

mm_prod=> set search_path = eliksir;
SET
mm_prod=> explain analyze select cs.* from contacts_segments cs inner join segments s on s.sid = cs.segment_id inner join contacts_lists cl on cl.email = cs.email and cl.lid = s.lid where cs.segment_id = 34983 and cl.lstatus = 'a';
                                                                             QUERY PLAN                                                                            
--------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Hash Join  (cost=452.96..1887.72 rows=1517 width=41) (actual time=3.980..8.554 rows=2945 loops=1)
   Hash Cond: ((cs.email)::text = (cl.email)::text)
   ->  Bitmap Heap Scan on contacts_segments cs  (cost=127.17..1488.89 rows=9258 width=41) (actual time=0.495..3.467 rows=9258 loops=1)
         Recheck Cond: (segment_id = 34983)
         Heap Blocks: exact=1246
         ->  Bitmap Index Scan on contacts_segments_segment_id_idx  (cost=0.00..124.86 rows=9258 width=0) (actual time=0.376..0.376 rows=9258 loops=1)
               Index Cond: (segment_id = 34983)
   ->  Hash  (cost=298.45..298.45 rows=2187 width=25) (actual time=3.476..3.476 rows=4645 loops=1)
         Buckets: 8192 (originally 4096)  Batches: 1 (originally 1)  Memory Usage: 324kB
         ->  Nested Loop  (cost=0.56..298.45 rows=2187 width=25) (actual time=0.019..2.726 rows=4645 loops=1)
               ->  Index Scan using segments_pkey on segments s  (cost=0.27..2.49 rows=1 width=8) (actual time=0.005..0.006 rows=1 loops=1)
                     Index Cond: (sid = 34983)
               ->  Index Scan using contacts_lists_lid_idx on contacts_lists cl  (cost=0.29..288.53 rows=744 width=25) (actual time=0.012..2.394 rows=4645 loops=1)
                     Index Cond: (lid = s.lid)
                     Filter: ((lstatus)::bpchar = 'a'::bpchar)
                     Rows Removed by Filter: 6628
 Planning Time: 23.416 ms
 Execution Time: 8.668 ms
(18 rows)

To give the schema:

mm_prod=> \d contacts_segments
                     Table "eliksir.contacts_segments"
   Column   |            Type             | Collation | Nullable | Default
------------+-----------------------------+-----------+----------+---------
 email      | email                       |           | not null |
 segment_id | integer                     |           | not null |
 entered_at | timestamp without time zone |           | not null | now()
 exited_at  | timestamp without time zone |           |          |
Indexes:
    "contacts_segments_pkey" PRIMARY KEY, btree (email, segment_id)
    "contacts_segments_segment_id_idx" btree (segment_id)
Foreign-key constraints:
    "contacts_segments_email_fkey" FOREIGN KEY (email) REFERENCES contacts(email) ON UPDATE CASCADE ON DELETE CASCADE DEFERRABLE
    "contacts_segments_segment_id_fkey" FOREIGN KEY (segment_id) REFERENCES segments(sid) ON DELETE CASCADE DEFERRABLE
Inherits: public.contacts_segments

mm_prod=> \d segments
                                         Table "eliksir.segments"
    Column    |            Type             | Collation | Nullable |                Default                
--------------+-----------------------------+-----------+----------+---------------------------------------
 sid          | integer                     |           | not null | nextval('segments_sid_seq'::regclass)
 lid          | integer                     |           | not null |
 segmentname  | text                        |           | not null |
 createdat    | timestamp without time zone |           | not null | now()
 label        | text                        |           |          |
 num_contacts | integer                     |           |          |
 cid          | integer                     |           |          |
 mid          | integer                     |           |          |
 original_sid | integer                     |           |          |
 archived_at  | timestamp without time zone |           |          |
Indexes:
    "segments_pkey" PRIMARY KEY, btree (sid)
    "segments_name" UNIQUE, btree (lid, segmentname)
Foreign-key constraints:
    "segments_cid_fkey" FOREIGN KEY (cid) REFERENCES campaigns(cid) ON UPDATE RESTRICT ON DELETE CASCADE DEFERRABLE
    "segments_lid_fkey" FOREIGN KEY (lid) REFERENCES lists(lid) ON UPDATE RESTRICT ON DELETE CASCADE DEFERRABLE
    "segments_mid_fkey" FOREIGN KEY (mid) REFERENCES mails(mid) ON UPDATE RESTRICT ON DELETE CASCADE DEFERRABLE
    "segments_original_sid_fkey" FOREIGN KEY (original_sid) REFERENCES segments(sid) ON UPDATE RESTRICT ON DELETE CASCADE DEFERRABLE
Referenced by:
    TABLE "contacts_segments" CONSTRAINT "contacts_segments_segment_id_fkey" FOREIGN KEY (segment_id) REFERENCES segments(sid) ON DELETE CASCADE DEFERRABLE
    TABLE "mails_segments" CONSTRAINT "mails_segments_sid_fkey" FOREIGN KEY (sid) REFERENCES segments(sid) ON UPDATE RESTRICT ON DELETE SET NULL DEFERRABLE
    TABLE "segments" CONSTRAINT "segments_original_sid_fkey" FOREIGN KEY (original_sid) REFERENCES segments(sid) ON UPDATE RESTRICT ON DELETE CASCADE DEFERRABLE
Inherits: public.segments

mm_prod=> \d contacts_lists
                                Table "eliksir.contacts_lists"
           Column           |            Type             | Collation | Nullable |   Default  
----------------------------+-----------------------------+-----------+----------+-------------
 email                      | email                       |           | not null |
 lid                        | integer                     |           | not null |
 lstatus                    | contact_status              |           | not null | 'a'::bpchar
 ladded                     | timestamp without time zone |           | not null | now()
 lstatuschanged             | timestamp without time zone |           | not null | now()
 skip_preexisting_campaigns | boolean                     |           |          |
 source_api_client_id       | uuid                        |           |          |
 source_integration_id      | text                        |           |          |
 source_form_id             | integer                     |           |          |
 source_user_id             | text                        |           |          |
 is_bulk_added              | boolean                     |           |          | false
Indexes:
    "contacts_lists_pkey" PRIMARY KEY, btree (email, lid)
    "contacts_lists_lid_idx" btree (lid) CLUSTER
    "contacts_lists_lstatus_idx" btree (lstatus)
    "contacts_lists_lstatuschanged_idx" btree (lstatuschanged)
Foreign-key constraints:
    "contacts_lists_email_fkey" FOREIGN KEY (email) REFERENCES contacts(email) ON UPDATE CASCADE ON DELETE CASCADE DEFERRABLE
    "contacts_lists_lid_fkey" FOREIGN KEY (lid) REFERENCES lists(lid) ON UPDATE RESTRICT ON DELETE CASCADE DEFERRABLE
    "contacts_lists_source_form_id_fkey" FOREIGN KEY (source_form_id) REFERENCES forms(id) ON UPDATE RESTRICT ON DELETE SET NULL DEFERRABLE
Triggers:
    [multiple triggers]
Inherits: public.contacts_lists

I tried investigated a bit PostgreSQL 12 vs 9.4 we were on a few weeks ago, and while this exact query can not be run on our 9.4 database (since some tables here are new), I found a similar query where the data is more or less unchanged in the old backup. In this query, planning time is much slower and constant in 12 compared to 9.4:

PostgreSQL 12.2:

mm_prod=> set search_path = eliksir, public;
SET
mm_prod=> explain analyze select * from segments_with_contacts swc inner join segments s using (sid) inner join contacts_lists cl on cl.email = swc.email and s.lid = cl.lid where swc.sid = 34983 and lstatus = 'a';
                                                                                       QUERY PLAN                                                                                        
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Hash Join  (cost=326.21..931.38 rows=402 width=187) (actual time=6.708..10.343 rows=2216 loops=1)
   Hash Cond: (swc.email = (cl.email)::citext)
   ->  Index Only Scan using segments_with_contacts_sid_lid_email_idx on segments_with_contacts swc  (cost=0.42..587.71 rows=2218 width=29) (actual time=0.013..0.546 rows=2216 loops=1)
         Index Cond: (sid = 34983)
         Heap Fetches: 2216
   ->  Hash  (cost=298.45..298.45 rows=2187 width=162) (actual time=6.687..6.687 rows=4645 loops=1)
         Buckets: 8192 (originally 4096)  Batches: 1 (originally 1)  Memory Usage: 817kB
         ->  Nested Loop  (cost=0.56..298.45 rows=2187 width=162) (actual time=0.019..3.315 rows=4645 loops=1)
               ->  Index Scan using segments_pkey on segments s  (cost=0.27..2.49 rows=1 width=74) (actual time=0.005..0.006 rows=1 loops=1)
                     Index Cond: (sid = 34983)
               ->  Index Scan using contacts_lists_lid_idx on contacts_lists cl  (cost=0.29..288.53 rows=744 width=88) (actual time=0.011..2.572 rows=4645 loops=1)
                     Index Cond: (lid = s.lid)
                     Filter: ((lstatus)::bpchar = 'a'::bpchar)
                     Rows Removed by Filter: 6628
 Planning Time: 1096.942 ms
 Execution Time: 10.473 ms
(16 rows)

PostgreSQL 9.4.12:

mm_prod=> set search_path = eliksir, public;
SET
mm_prod=> explain analyze select * from segments_with_contacts swc inner join segments s using (sid) inner join contacts_lists cl on cl.email = swc.email and s.lid = cl.lid where swc.sid = 34983 and lstatus = 'a';
                                                                          QUERY PLAN                                                                          
---------------------------------------------------------------------------------------------------------------------------------------------------------------
 Hash Join  (cost=700.92..1524.11 rows=444 width=187) (actual time=13.800..20.009 rows=2295 loops=1)
   Hash Cond: (swc.email = (cl.email)::citext)
   ->  Bitmap Heap Scan on segments_with_contacts swc  (cost=110.44..888.50 rows=2325 width=29) (actual time=0.318..0.737 rows=2295 loops=1)
         Recheck Cond: (sid = 34983)
         Heap Blocks: exact=19
         ->  Bitmap Index Scan on segments_with_contacts_sid_lid_email_idx  (cost=0.00..109.86 rows=2325 width=0) (actual time=0.299..0.299 rows=2335 loops=1)
               Index Cond: (sid = 34983)
   ->  Hash  (cost=559.75..559.75 rows=2459 width=162) (actual time=13.401..13.401 rows=4624 loops=1)
         Buckets: 1024  Batches: 1  Memory Usage: 749kB
         ->  Nested Loop  (cost=51.55..559.75 rows=2459 width=162) (actual time=1.375..7.515 rows=4624 loops=1)
               ->  Index Scan using segments_pkey on segments s  (cost=0.28..8.29 rows=1 width=74) (actual time=0.012..0.015 rows=1 loops=1)
                     Index Cond: (sid = 34983)
               ->  Bitmap Heap Scan on contacts_lists cl  (cost=51.27..543.86 rows=760 width=88) (actual time=1.355..6.525 rows=4624 loops=1)
                     Recheck Cond: (lid = s.lid)
                     Filter: ((lstatus)::bpchar = 'a'::bpchar)
                     Rows Removed by Filter: 6428
                     Heap Blocks: exact=455
                     ->  Bitmap Index Scan on contacts_lists_lid_idx  (cost=0.00..51.08 rows=1439 width=0) (actual time=1.275..1.275 rows=11533 loops=1)
                           Index Cond: (lid = s.lid)
 Planning time: 22.120 ms
 Execution time: 20.337 ms
(21 rows)

PostgreSQL 12.2 is run on EPYC 7302P 16-core, 64GB RAM, 2x NVMe disks in RAID1, Ubuntu 18.04.1 running 5.0.0-37 HWE kernel. Some settings:

constraint_exclusion = partition (I tried setting this to off or on, to see if that made any difference; nope)
default_statistics_target = 1000
effective_cache_size = 48GB
effective_io_concurrency = 200
max_worker_processes = 16
random_page_cost = 1.1
shared_buffers = 16GB
work_mem = 16MB

Thanks for any guidance.

-- a.

pgsql-performance by date:

Previous
From: Justin Pryzby
Date:
Subject: Re: Slow ext'd query via client native implementation vs. libpq &simple psql
Next
From: Andreas Kretschmer
Date:
Subject: Re: Slow planning time when public schema included (12 vs. 9.4)