Query with high planning time at version 11.1 compared versions 10.5 and 11.0
Hi, I'm running performance tests for my application at version 11.1 and encountered queries with high planning time compared to the same planning, running at versions 10.5 and 11.0. -- Day and store where the highest price variation of a given product occurred in a given period explain analyze select l_variacao.fecha, l_variacao.loccd as "Almacen", l_variacao.pant as "Precio anterior", l_variacao.patual as "Precio atual", max_variacao.var_max as "Variación máxima (Agua)" from (select p.fecha, p.loccd, p.plusalesprice patual, da.plusalesprice pant, abs(p.plusalesprice - da.plusalesprice) as var from precio p, (select p.fecha, p.plusalesprice, p.loccd from precio p where p.fecha between '2017-03-01' and '2017-03-02'and p.pluid = 2) da where p.fecha between '2017-03-01' and '2017-03-02'and p.pluid = 2 and p.loccd = da.loccd and p.fecha = da.fecha + 1) l_variacao, (select max(abs(p.plusalesprice - da.plusalesprice)) as var_max from precio p, (select p.fecha, p.plusalesprice, p.loccd from precio p where p.fecha between '2017-03-01' and '2017-03-02'and p.pluid = 2) da where p.fecha between '2017-03-01' and '2017-03-02'and p.pluid = 2 and p.loccd = da.loccd and p.fecha = da.fecha + 1) max_variacao where max_variacao.var_max = l_variacao.var; Formatted explain: https://explain.depesz.com/s/mUkP And below are the times generated by EXPLAIN ANALYZE: 10.5 Planning time: 126.080 ms Execution time: 2.306 ms 11.0 Planning Time: 7.238 ms Planning Time: 2.638 ms 11.5 Planning Time: 15138.533 ms Execution Time: 2.310 ms All 3 EXPLAIN show exactly the same plan, but version 11.1 is consuming about 15s more to perform the planning. Below are some additional OS information: CPU: 16 RAM: 128GB Disk: SSD OS: CentOS Linux release 7.5.1804 Is there any configuration I have to do in 11.1 to achieve the same planning performance as in previous versions? Regards, Sanyo Capobiango
Re: Query with high planning time at version 11.1 compared versions 10.5 and 11.0
Sanyo Moura writes: > And below are the times generated by EXPLAIN ANALYZE: > 10.5 > Planning time: 126.080 ms > Execution time: 2.306 ms > 11.0 > Planning Time: 7.238 ms > Planning Time: 2.638 ms > 11.5(I assume you mean 11.1 here) > Planning Time: 15138.533 ms > Execution Time: 2.310 ms There were no changes between 11.0 and 11.1 that look like they'd affect planning time. Nor does it seem particularly credible that planning time would have dropped by a factor of 15 between 10.x and 11.x, especially not given that the resulting plan didn't change. I think you've got some external factor causing long planning times --- maybe something taking an exclusive lock on one of the tables, or on pg_statistic? regards, tom lane
Re: Query with high planning time at version 11.1 compared versions 10.5 and 11.0
Hello Tom, Both versions 10.5 and 11.1 are running on the same test server. What I did was migrate the database from 10.5 to 11.1 via pg_upgrade. After successful execution, I performed "vacuumdb --all --analyze-in-stages". Thanks, Sanyo Capobiango Em ter, 27 de nov de 2018 às 13:00, Tom Lane escreveu: > Sanyo Moura writes: > > And below are the times generated by EXPLAIN ANALYZE: > > > 10.5 > > Planning time: 126.080 ms > > Execution time: 2.306 ms > > > 11.0 > > Planning Time: 7.238 ms > > Planning Time: 2.638 ms > > > 11.5(I assume you mean 11.1 here) > > Planning Time: 15138.533 ms > > Execution Time: 2.310 ms > > There were no changes between 11.0 and 11.1 that look like they'd affect > planning time. Nor does it seem particularly credible that planning time > would have dropped by a factor of 15 between 10.x and 11.x, especially > not given that the resulting plan didn't change. I think you've got some > external factor causing long planning times --- maybe something taking an > exclusive lock on one of the tables, or on pg_statistic? > > regards, tom lane >
Re: Query with high planning time at version 11.1 compared versions 10.5 and 11.0
On Tue, Nov 27, 2018 at 9:17 AM Sanyo Moura wrote: > Hi, > > I'm running performance tests for my application at version 11.1 and > encountered > queries with high planning time compared to the same planning, running at > versions 10.5 and 11.0. > Can you reproduce the regression if the tables are empty? If so, can you share the create script that creates the tables? Cheers, Jeff >
Re: Query with high planning time at version 11.1 compared versions 10.5 and 11.0
Hello Jeff, My table (PRICE) is partitioned and contains 730 partitions. Each partition contains 1 day of data. I performed the same test now with restriction (WHERE) in only 1 day (1 partition), but doing SELECT in the virtual table PRICE. I got the same delay in planning. However, when I changed my query to use the partition directly, the plan ran instantaneously. I believe the problem should be in some internal code related to scanning the partitions for the planning. Does it make sense? Thanks, Sanyo Capobiango Em ter, 27 de nov de 2018 às 17:35, Jeff Janes escreveu: > > > On Tue, Nov 27, 2018 at 9:17 AM Sanyo Moura wrote: > >> Hi, >> >> I'm running performance tests for my application at version 11.1 and >> encountered >> queries with high planning time compared to the same planning, running at >> versions 10.5 and 11.0. >> > > Can you reproduce the regression if the tables are empty? If so, can you > share the create script that creates the tables? > > Cheers, > > Jeff > >>
Re: Query with high planning time at version 11.1 compared versions 10.5 and 11.0
Hello again Jeff,
Below is the script that creates one partition table:
CREATE TABLE public.precio_20170301 PARTITION OF public.precio
(
CONSTRAINT precio_20170301_pkey PRIMARY KEY (fecha, pluid, loccd),
CONSTRAINT precio_20170301_almacen_fk FOREIGN KEY (loccd)
REFERENCES public.almacen (loccd) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION,
CONSTRAINT precio_20170301_producto_fk FOREIGN KEY (pluid)
REFERENCES public.producto (pluid) MATCH SIMPLE
ON UPDATE NO ACTION
ON DELETE NO ACTION
)
FOR VALUES FROM ('2017-03-01') TO ('2017-03-02')
TABLESPACE pg_default;
I reproduce same test in a empty partition and got same result (15s) at
planning
time when I used the virtual table (PRECIO), and an instantly EXPLAIN when
I used
the partition directly.
Regards,
Sanyo Capobiango
Em ter, 27 de nov de 2018 às 17:35, Jeff Janes
escreveu:
>
>
> On Tue, Nov 27, 2018 at 9:17 AM Sanyo Moura wrote:
>
>> Hi,
>>
>> I'm running performance tests for my application at version 11.1 and
>> encountered
>> queries with high planning time compared to the same planning, running at
>> versions 10.5 and 11.0.
>>
>
> Can you reproduce the regression if the tables are empty? If so, can you
> share the create script that creates the tables?
>
> Cheers,
>
> Jeff
>
>>
Re: Query with high planning time at version 11.1 compared versions 10.5 and 11.0
On Tue, Nov 27, 2018 at 06:30:04PM -0200, Sanyo Moura wrote: >>> I'm running performance tests for my application at version 11.1 and >>> encountered >>> queries with high planning time compared to the same planning, running at >>> versions 10.5 and 11.0. > > Below is the script that creates one partition table: Would you send the CREATE TABLE or \d for precio, produto, and almacen ? Are the 2 referenced tables also empty or can you reproduce the problem if they are (like in a separate database) ? Do you still have an instance running 10.5 ? Or did you find the planning time in logs (like autoexplain) ? Are any of your catalog tables bloated or indexes fragmented ? I assume catalog tables and their indices should all be much smaller than shared_buffers. SELECT relpages, relname FROM pg_class WHERE relnamespace='pg_catalog'::regnamespace ORDER BY 1 DESC LIMIT 9; Can you compare pg_settings between the servers ? Either from a live server or historic postgresql.conf or from memory if need be. https://wiki.postgresql.org/wiki/Server_Configuration Justin
Re: Query with high planning time at version 11.1 compared versions 10.5 and 11.0
On Tue, Nov 27, 2018 at 9:17 AM Sanyo Moura wrote:
>>> I'm running performance tests for my application at version 11.1 and
>>> encountered queries with high planning time compared to the same planning,
>>> running at versions 10.5 and 11.0.
I was able to reproduce this behavior.
For my version of the query:
On PG10.6
| Result (cost=0.00..0.00 rows=0 width=24)
| One-Time Filter: false
|Time: 408.335 ms
On PG11.1
| Result (cost=0.00..0.00 rows=0 width=24)
| One-Time Filter: false
|Time: 37487.364 ms (00:37.487)
Perf shows me:
47.83% postmaster postgres[.] bms_overlap
45.30% postmaster postgres[.] add_child_rel_equivalences
1.26% postmaster postgres[.]
generate_join_implied_equalities_for_ecs
CREATE TABLE producto (pluid int unique);
CREATE TABLE almacen (loccd int unique);
CREATE TABLE precio(fecha timestamp, pluid int, loccd int, plusalesprice int)
PARTITION BY RANGE (fecha);
SELECT 'CREATE TABLE public.precio_'||i||' PARTITION OF public.precio (PRIMARY
KEY (fecha, pluid, loccd), CONSTRAINT precio_20170301_almacen_fk FOREIGN KEY
(loccd) REFERENCES public.almacen (loccd) MATCH SIMPLE ON UPDATE NO ACTION ON
DELETE NO ACTION, CONSTRAINT precio_20170301_producto_fk FOREIGN KEY (pluid)
REFERENCES public.producto (pluid) MATCH SIMPLE ON UPDATE NO ACTION ON DELETE
NO ACTION) FOR VALUES FROM ('''||a||''')TO('''||b||''') TABLESPACE pg_default'
FROM (SELECT '1990-01-01'::timestamp+(i||'days')::interval a,
'1990-01-02'::timestamp+(i||'days')::interval b, i FROM generate_series(1,999)
i)x;
\gexec
\timing
explain SELECT l_variacao.fecha, l_variacao.loccd , l_variacao.pant ,
l_variacao.patual , max_variacao.var_max FROM (SELECT p.fecha, p.loccd,
p.plusalesprice patual, da.plusalesprice pant, abs(p.plusalesprice -
da.plusalesprice) as var from precio p, (SELECT p.fecha, p.plusalesprice,
p.loccd from precio p WHERE p.fecha between '2017-03-01' and '2017-03-02' and
p.pluid = 2) da WHERE p.fecha between '2017-03-01' and '2017-03-02' and p.pluid
= 2 and p.loccd = da.loccd and p.fecha = da.fecha) l_variacao, (SELECT
max(abs(p.plusalesprice - da.plusalesprice)) as var_max from precio p, (SELECT
p.fecha, p.plusalesprice, p.loccd from precio p WHERE p.fecha between
'2017-03-01' and '2017-03-02' and p.pluid = 2) da WHERE p.fecha between
'2017-03-01' and '2017-03-02' and p.pluid = 2 and p.loccd = da.loccd and
p.fecha = da.fecha) max_variacao WHERE max_variacao.var_max = l_variacao.var;
Since I don't know the original table definitions, I removed two "+1" from the
given sql to avoid: "ERROR: operator does not exist: timestamp without time
zone + integer"
Justin
Re: Query with high planning time at version 11.1 compared versions 10.5 and 11.0
Thanks a lot Justin,
At this moment I can not help you with what you asked for, but tomorrow
morning I will send other information.
I believe Postgres 11.1 is somehow taking a lot of planning time when
analyzing which partitions are needed in execution.
Sanyo
Em ter, 27 de nov de 2018 às 22:44, Justin Pryzby
escreveu:
> On Tue, Nov 27, 2018 at 9:17 AM Sanyo Moura wrote:
> >>> I'm running performance tests for my application at version 11.1 and
> >>> encountered queries with high planning time compared to the same
> planning,
> >>> running at versions 10.5 and 11.0.
>
> I was able to reproduce this behavior.
>
> For my version of the query:
>
> On PG10.6
> | Result (cost=0.00..0.00 rows=0 width=24)
> | One-Time Filter: false
> |Time: 408.335 ms
>
> On PG11.1
> | Result (cost=0.00..0.00 rows=0 width=24)
> | One-Time Filter: false
> |Time: 37487.364 ms (00:37.487)
>
> Perf shows me:
> 47.83% postmaster postgres[.] bms_overlap
> 45.30% postmaster postgres[.] add_child_rel_equivalences
>1.26% postmaster postgres[.]
> generate_join_implied_equalities_for_ecs
>
> CREATE TABLE producto (pluid int unique);
> CREATE TABLE almacen (loccd int unique);
> CREATE TABLE precio(fecha timestamp, pluid int, loccd int, plusalesprice
> int) PARTITION BY RANGE (fecha);
> SELECT 'CREATE TABLE public.precio_'||i||' PARTITION OF public.precio
> (PRIMARY KEY (fecha, pluid, loccd), CONSTRAINT precio_20170301_almacen_fk
> FOREIGN KEY (loccd) REFERENCES public.almacen (loccd) MATCH SIMPLE ON
> UPDATE NO ACTION ON DELETE NO ACTION, CONSTRAINT
> precio_20170301_producto_fk FOREIGN KEY (pluid) REFERENCES public.producto
> (pluid) MATCH SIMPLE ON UPDATE NO ACTION ON DELETE NO ACTION) FOR VALUES
> FROM ('''||a||''')TO('''||b||''') TABLESPACE pg_default' FROM (SELECT
> '1990-01-01'::timestamp+(i||'days')::interval a,
> '1990-01-02'::timestamp+(i||'days')::interval b, i FROM
> generate_series(1,999) i)x;
>
> \gexec
> \timing
> explain SELECT l_variacao.fecha, l_variacao.loccd , l_variacao.pant ,
> l_variacao.patual , max_variacao.var_max FROM (SELECT p.fecha, p.loccd,
> p.plusalesprice patual, da.plusalesprice pant, abs(p.plusalesprice -
> da.plusalesprice) as var from precio p, (SELECT p.fecha, p.plusalesprice,
> p.loccd from precio p WHERE p.fecha between '2017-03-01' and '2017-03-02'
> and p.pluid = 2) da WHERE p.fecha between '2017-03-01' and '2017-03-02' and
> p.pluid = 2 and p.loccd = da.loccd and p.fecha = da.fecha) l_variacao,
> (SELECT max(abs(p.plusalesprice - da.plusalesprice)) as var_max from precio
> p, (SELECT p.fecha, p.plusalesprice, p.loccd from precio p WHERE p.fecha
> between '2017-03-01' and '2017-03-02' and p.pluid = 2) da WHERE p.fecha
> between '2017-03-01' and '2017-03-02' and p.pluid = 2 and p.loccd =
> da.loccd and p.fecha = da.fecha) max_variacao WHERE max_variacao.var_max =
> l_variacao.var;
>
> Since I don't know the original table definitions, I removed two "+1" from
> the
> given sql to avoid: "ERROR: operator does not exist: timestamp without
> time zone + integer"
>
> Justin
>
Re: Query with high planning time at version 11.1 compared versions 10.5 and 11.0
On Tue, Nov 27, 2018 at 06:44:02PM -0600, Justin Pryzby wrote: > On Tue, Nov 27, 2018 at 9:17 AM Sanyo Moura wrote: > >>> I'm running performance tests for my application at version 11.1 and > >>> encountered queries with high planning time compared to the same planning, > >>> running at versions 10.5 and 11.0. > > I was able to reproduce this behavior. I take that back, in part.. My query (with One-Time Filter: false) has high planning time under 11.0, also: | Result (cost=0.00..0.00 rows=0 width=24) | One-Time Filter: false |Time: 48335.098 ms (00:48.335) Justin
Re: Query with high planning time at version 11.1 compared versions 10.5 and 11.0
I currently have version 11.1 and 10.6 running on the same linux server. In both Postgres the "Price" table has 730 partitions. However, in the test I did in version 11.0, "Precio" is partitioned into only 21 partitions. So it really is a problem introduced in version 11, and it has to do with a large number of partitions in a table. Sanyo Em ter, 27 de nov de 2018 às 23:27, Justin Pryzby escreveu: > On Tue, Nov 27, 2018 at 06:44:02PM -0600, Justin Pryzby wrote: > > On Tue, Nov 27, 2018 at 9:17 AM Sanyo Moura > wrote: > > >>> I'm running performance tests for my application at version 11.1 and > > >>> encountered queries with high planning time compared to the same > planning, > > >>> running at versions 10.5 and 11.0. > > > > I was able to reproduce this behavior. > > I take that back, in part.. > > My query (with One-Time Filter: false) has high planning time under 11.0, > also: > > | Result (cost=0.00..0.00 rows=0 width=24) > | One-Time Filter: false > |Time: 48335.098 ms (00:48.335) > > Justin >
Re: Query with high planning time at version 11.1 compared versions 10.5 and 11.0
On Tue, Nov 27, 2018 at 11:36:09PM -0200, Sanyo Moura wrote:
> However, in the test I did in version 11.0, "Precio" is partitioned into
> only 21 partitions. So it really is a problem introduced in version 11, and
> it has to do with a large number of partitions in a table.
Thanks for confirming. My test works fine without FK CONSTRAINTs; as you said,
it's an issue of unreasonably high overhead of many partitions.
SELECT 'CREATE TABLE public.precio_'||i||' PARTITION OF public.precio (PRIMARY
KEY (fecha, pluid, loccd) ) FOR VALUES FROM ('''||a||''')TO('''||b||''') ' FROM
(SELECT '1990-01-01'::timestamp+(i||'days')::interval a,
'1990-01-02'::timestamp+(i||'days')::interval b, i FROM generate_series(1,999)
i)x;
This issue was discussed here:
https://www.postgresql.org/message-id/flat/94dd7a4b-5e50-0712-911d-2278e055c622%40dalibo.com
Which culminated in this commit.
|commit 7d872c91a3f9d49b56117557cdbb0c3d4c620687
|Author: Alvaro Herrera
|Date: Tue Jun 26 10:35:26 2018 -0400
|
|Allow direct lookups of AppendRelInfo by child relid
I tried with PG11.1 the test given here:
https://www.postgresql.org/message-id/CAKJS1f8qkcwr2DULd%2B04rBmubHkKzp4abuFykgoPUsVM-4-38g%40mail.gmail.com
with 999 partitions: Planning Time: 50.142 ms
with partitions: Planning Time: 239.284 ms
..close enough to what was reported.
So it seems there's something about your query which isn't handled as intended.
Adding relevant parties to Cc - find current thread here:
https://www.postgresql.org/message-id/flat/CAO698qZnrxoZu7MEtfiJmpmUtz3AVYFVnwzR%2BpqjF%3DrmKBTgpw%40mail.gmail.com
Justin
Re: Query with high planning time at version 11.1 compared versions 10.5 and 11.0
On Wed, 28 Nov 2018 at 03:16, Sanyo Moura wrote: > 11.0 > Planning Time: 7.238 ms > Planning Time: 2.638 ms > > 11.5 > Planning Time: 15138.533 ms > Execution Time: 2.310 ms Does it still take that long after running ANALYZE on the partitioned table? -- David Rowley http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services
Re: Query with high planning time at version 11.1 compared versions 10.5 and 11.0
On Wed, Nov 28, 2018 at 05:03:15PM +1300, David Rowley wrote: > Does it still take that long after running ANALYZE on the partitioned table? Yes ; I've just reproduced the problem with a variation on Sanyo's query, retrofitted onto the empty "partbench" table you used for testing in July: https://www.postgresql.org/message-id/CAKJS1f8qkcwr2DULd%2B04rBmubHkKzp4abuFykgoPUsVM-4-38g%40mail.gmail.com Note, Sanyo's original query appears to be a poor-man's window function, joining two subqueries on a.value=max(b.value). I reduced issue to this: |postgres=# ANALYZE partbench; |postgres=# explain SELECT * FROM (SELECT a.i2-b.i2 n FROM partbench a, (SELECT i2 FROM partbench)b)b, (SELECT max(partbench.i3) m FROM partbench, (SELECT i3 FROM partbench)y )y WHERE m=n; |Time: 31555.582 ms (00:31.556) Justin
