Slow planning time when public schema included (12 vs. 9.4)

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.