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 , 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_
Re: Slow planning time when public schema included (12 vs. 9.4)
Am 21.03.20 um 13:02 schrieb Anders Steinlein: default_statistics_target = 1000 not sure if this be the culprit here, but i think this is way too high. Leave it at the normal value of 100 and raise it only for particular tables and columns. Regards, Andreas -- 2ndQuadrant - The PostgreSQL Support Company. www.2ndQuadrant.com
Re: Slow planning time when public schema included (12 vs. 9.4)
Anders Steinlein writes:
> We haven't noticed any issues with this before now, until we started seeing
> really slow planning time on some relatively simple queries:
> ...
> 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:
I notice a difference in these plans:
> 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)
^^ ^^
> 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)
I think what is happening is that the "cl.email = cs.email" clause
is resolving as a different operator depending on your search path;
probably there is a "citext = citext" operator in the public
schema, and if available the parser will think it's a better match
than the "text = text" operator. However, "citext = citext" can
be orders of magnitude slower, depending on what locale settings
you're using. That's affecting your planning time (since the
planner will apply the operator to the values available from
pg_stats), and it's also visibly affecting the query runtime.
Not sure why you'd not have seen the same effect in your 9.4
installation, but maybe you had citext installed somewhere else?
regards, tom lane
Re: Slow planning time when public schema included (12 vs. 9.4)
On Sat, Mar 21, 2020 at 2:37 PM Andreas Kretschmer wrote: > > > Am 21.03.20 um 13:02 schrieb Anders Steinlein: > > default_statistics_target = 1000 > > not sure if this be the culprit here, but i think this is way too high. > Leave it at the normal value of 100 and raise it only for particular > tables and columns. > It may very well be too high, but the 9.4 instance also has default_statistics_target = 1000. Best, -- a.
Re: Slow planning time when public schema included (12 vs. 9.4)
On Sat, Mar 21, 2020 at 3:26 PM Tom Lane wrote: > Anders Steinlein writes: > > We haven't noticed any issues with this before now, until we started > seeing > > really slow planning time on some relatively simple queries: > > ... > > 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: > > I notice a difference in these plans: > > > 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) > ^^ ^^ > > > 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) > > > I think what is happening is that the "cl.email = cs.email" clause > is resolving as a different operator depending on your search path; > probably there is a "citext = citext" operator in the public > schema, and if available the parser will think it's a better match > than the "text = text" operator. However, "citext = citext" can > be orders of magnitude slower, depending on what locale settings > you're using. That's affecting your planning time (since the > planner will apply the operator to the values available from > pg_stats), and it's also visibly affecting the query runtime. > > Not sure why you'd not have seen the same effect in your 9.4 > installation, but maybe you had citext installed somewhere else? > The citext extension is installed in the public schema in both instances. Also, the second query example that I could run on both 12 and 9.4 runs with the citext comparison in both cases. From 9.4: 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) mm2_prod=> \d segments_with_contacts Materialized view "eliksir.segments_with_contacts" Column | Type | Modifiers +-+--- lid| integer | sid| integer | email | citext | The tables segments and contacts_lists are identical on the two instances, i.e. both are using citext (email domain using the citext type) on both 12 and 9.4, with the citext extension in the public schema. Is it the lc_collate setting citext cares about? lc_collate=nb_NO.UTF-8 on both 9.4 and 12. So I don't understand this big difference? Because it does seem like citext is indeed the difference. I tried to modify the query to cast before joining, and it is indeed much improved: mm_prod=> set search_path = eliksir, public; 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 lower(cl.email::text) = lower(cs.email::text) and cl.lid = s.lid where cs.segment_id = 34983 and cl.lstatus = 'a'; QUERY PLAN Merge Join (cost=2518.61..4565.20 rows=101259 width=41) (actual time=47.278..51.686 rows=2945 loops=1) Merge Cond: ((lower((cl.email)::text)) = (lower((cs.email)::text))) -> Sort (cost=419.78..425.24 rows=2187 width=25) (actual time=18.283..18.516 rows=4646 loops=1) Sort Key: (lower((cl.email)::text)) Sort Method: quicksort Memory: 665kB -> Nested Loop (cost=0.56..298.45 rows=2187 width=25) (actual time=0.057..9.805 rows=4646 loops=1) -> Index Scan using segments_pkey on segments s (cost=0.27..2.49 rows=1 width=8) (actual time=0.021..0.022 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.023..4.953 rows=4646 loops=1) Index Cond: (lid = s.lid) Filter: ((lstatus)::bpchar = 'a'::bpchar) Rows Removed by Filter: 6628 -> Sort (cost=2098.83..2121.98 rows=9258 width=41) (actual time=28.988..29.373 rows=9258 loops=1) Sort Key: (lower((cs.email)::text)) Sort Method: quicksort Memory: 1598kB -> Bitmap Heap Scan on contacts_segments cs (cost=127.17..1488.89 rows=9258 width=41) (actual time=0.511..7.910 rows=9258 loops=1) Recheck Cond: (segment_id = 3
Re: Slow planning time when public schema included (12 vs. 9.4)
Anders Steinlein writes: > On Sat, Mar 21, 2020 at 3:26 PM Tom Lane wrote: >> Not sure why you'd not have seen the same effect in your 9.4 >> installation, but maybe you had citext installed somewhere else? > The tables segments and contacts_lists are identical on the two instances, > i.e. both are using citext (email domain using the citext type) on both 12 > and 9.4, with the citext extension in the public schema. Is it the > lc_collate setting citext cares about? lc_collate=nb_NO.UTF-8 on both 9.4 > and 12. I think it depends on both lc_collate and lc_ctype, since basically what it's doing is lower() on each string and then a strcoll() comparison. The strcoll() part should be pretty much equivalent to text comparisons, though ... or, hmm, maybe not. texteq() knows it can reduce that to just a memcmp bitwise-equality test, but citext doesn't have that optimization. > So I don't understand this big difference? Because it does seem like citext > is indeed the difference. It seems odd to me too. I'm not at all surprised that citext comparison is way slower than text, but I am surprised that you don't see that on 9.4 as well. Is lc_ctype the same in both installs? For that matter, is the underlying libc the same? We have seen large performance discrepancies between different libc versions in this area. If you're interested in digging further, getting a "perf" profile while running the problem query over and over would likely yield some insight about where the time is going. https://wiki.postgresql.org/wiki/Profiling_with_perf regards, tom lane
Re: Slow planning time when public schema included (12 vs. 9.4)
On Sat, Mar 21, 2020 at 8:35 PM Tom Lane wrote: > Anders Steinlein writes: > > So I don't understand this big difference? Because it does seem like > citext > > is indeed the difference. > > It seems odd to me too. I'm not at all surprised that citext comparison > is way slower than text, but I am surprised that you don't see that on 9.4 > as well. Indeed. But also, how come this is part of the planner time? I would think that would be part of the execution time? (Just a detail I'm curious about.) Is lc_ctype the same in both installs? Yes, lc_ctype is also nb_NO.UTF-8 on both installs. > For that matter, is the underlying libc the same? We have seen large > performance discrepancies > between different libc versions in this area. > This they most definitely are not. 9.4 was running on an old box, Ubuntu 12.04, while 12 is on an up-to-date Ubuntu 18.04 LTS. AFAICS, 2.15 on the 9.4 box and 2.27 on the 12 box. If you're interested in digging further, getting a "perf" profile while > running the problem query over and over would likely yield some insight > about where the time is going. > I collected a profile now, but I've never done this before so I'm unsure how to read the report. I'll email you directly with a link to the perf.data file, if you would be so kind as to take a quick look. From what little I think I understand, towlower from libc seems to take up 32% of the total time, although that by itself doesn't seem to explain almost 2 second planner time vs. 20ms... Should really citext/libc string comparison "issues" cause this order of magnitude slower planner time? Best, -- a.
Re: Slow planning time when public schema included (12 vs. 9.4)
Anders Steinlein writes: > On Sat, Mar 21, 2020 at 8:35 PM Tom Lane wrote: >> It seems odd to me too. I'm not at all surprised that citext comparison >> is way slower than text, but I am surprised that you don't see that on 9.4 >> as well. > Indeed. But also, how come this is part of the planner time? I would think > that would be part of the execution time? (Just a detail I'm curious about.) As part of estimating the size of a join, the planner will run through all the most-common-values available from pg_stats and see which values from one table match to which values from the other. If you have a lot of MCVs (which'd involve a fairly flat, but not unique, data distribution and a large stats target setting) and a slow join operator, it's not hard for that to take a lot of time. You might care to look into pg_stats and see just how big those arrays are for each of these columns. But 9.4 did that too, so we're still at a loss as to why v12 is so much slower. > This they most definitely are not. 9.4 was running on an old box, Ubuntu > 12.04, while 12 is on an up-to-date Ubuntu 18.04 LTS. AFAICS, 2.15 on the > 9.4 box and 2.27 on the 12 box. I'm suspicious that the root issue has to do with libc differences, but I haven't any hard data to back that up with. Another possibility perhaps is that v12's ANALYZE is collecting a lot more "common" values than 9.4 did. Whether it is or not, the advice you already got to ratchet down the stats target would likely be helpful to reduce the planning time. regards, tom lane
