Thread: pg12 partitions show bad performance vs pg96

On Mon, 9 Mar 2020 at 05:05, Mariel Cherkassky
<mariel.cherkassky@gmail.com> wrote:
> PG12 :
>  Planning Time: 8.157 ms
>  Execution Time: 2.920 ms
> (22 rows)
>
>
> PG96 :
>  Planning time: 0.815 ms
>  Execution time: 0.158 ms
> (12 rows)

8 ms seems pretty slow to planning that query. Does the planning time
drop if you execute this multiple times in the same session? Does the
time change if you try again without any foreign keys?

The planning time for the partitioned case is certainly going to take
longer. Partitioned tables are never going to improve the times of
query planning. It's only possible that they'll improve the
performance during query execution.

For such small fast queries as the ones you've shown, it's important
to remember that more complex query plans (ones with more nodes) do
lead to longer times for executor startup and shutdown.   EXPLAIN
(without ANALYZE), will perform query planning and executor
startup/shutdown. If you enable \timing on in psql and test the
EXPLAIN performance of these queries in each version, then you might
get an idea of where the overheads are.

Additionally, you're unlikely to see performance improvements with
table partitioning unless you're accessing many rows and partitioning
allows the data locality of the rows that you are accessing to
improve. i.e accesses fewer buffers and/or improves cache hit ratios.
In PG12, if the partition pruning can be done during query planning
then the planning and executor startup overhead is much lower since
there are fewer relations to generate access paths for and fewer nodes
in the final plan. This also improves the situation during execution
as it means fewer locks to take and fewer nodes to startup/shutdown.

> As you can see, the results are better in pg96. This example only shows the results for a small data set. In bigger
datasets I get a bigger diff...
 

Can you share the results of that?

> I tried changing many postgresql.conf parameters that were added (max_workers_per_gather,enable_partitionwise_join
andso on..).
 

The former only does anything for parallel queries. None of the plans
you've shown are parallel ones.   The latter also does not count in
this case. It only counts when joining two identically partitioned
tables.

> I dont understand why in pg12 it scans all the partitions instead of the relevant one..

If you'd specified a specific "device" in the query SQL, then the
query planner would know which partition to scan for that particular
device. However, since you're looking up the device in another table
and performing a join, the device is only known during query
execution. The plan nodes for the non-matching partitions do go
through executor startup, but they're not scanned during execution, as
you've seen with the "(never executed)" appearing in the EXPLAIN
ANALYZE output.  Since executor startup occurs before execution, the
device you mean is still unknown during executor startup, so the
executor must startup the nodes for all partitions that are in the
plan. Starting up a plan node is not free, but not really very
expensive either. However, the overhead of it might be quite large
proportionally in your case since the executor is doing so little
work.

The most basic guidelines for table partitioning are, don't partition
your tables unless it's a net win.   If partitioning was always
faster, we'd just have designed Postgres to implicitly partition all
of your tables for you. There are some other guidelines in [1].

[1] https://www.postgresql.org/docs/12/ddl-partitioning.html#DDL-PARTITIONING-DECLARATIVE-BEST-PRACTICES

David

On Sun, Mar 08, 2020 at 06:05:26PM +0200, Mariel Cherkassky wrote:
> In pg12 I created  a table with 3 hash partitiones :
> create table iot_data(id serial ,data text,metadata bigint,device bigint
> references iot_device(id),primary key(id,device)) partition by hash(device);

> and now for the performance:
> query :  explain analyze select * from iot_data da,iot_device de where
> de.name in ('50a') and de.id = da.device and da.metadata=50 and
> lower(da.data) like '50';

> I dont understand why in pg12 it scans all the partitions instead of the
> relevant one..

As you noticed, it doesn't actually scan them.  I believe v11 "partition
elimination during query execution" is coming into play here.  There's no
option to disable that, but as a quick test, you could possibly try under PG10
(note, that doesn't support inherited indexes).  Or you could try to profile
under PG12 (and consider comparing with pg13dev).

You partitioned on hash(iot_data.device), but your query doesn't specify
device, except that da.device=de.id AND de.name IN ('50').  If that's a typical
query, maybe it'd work better to partition on metadata or lower(name) (or
possibly both).

On Sun, Mar 08, 2020 at 06:05:26PM +0200, Mariel Cherkassky wrote:
> PG12 :
>  Nested Loop  (cost=5.16..773.61 rows=2 width=43) (actual time=2.858..2.858
> rows=0 loops=1)
...
>          ->  Bitmap Heap Scan on iot_data_1 da_1  (cost=5.20..249.32 rows=2
> width=37) (NEVER EXECUTED)
...
>  Planning Time: 8.157 ms
>  Execution Time: 2.920 ms

> PG96 :
>  Nested Loop  (cost=6.57..397.19 rows=2 width=44) (actual time=0.121..0.121
> rows=0 loops=1)
...
>  Planning time: 0.815 ms
>  Execution time: 0.158 ms

-- 
Justin

On Mon, Mar 09, 2020 at 12:31:15PM +0200, Mariel Cherkassky wrote:
> > I tried to do even something simpler, run the query with only the
> > partition column in the where clause and the results werent good for pg12 :
>
> PG12 :
> postgres=# explain analyze select * from iot_data where device=51;
>                                                               QUERY PLAN
>
---------------------------------------------------------------------------------------------------------------------------------------
>  Gather  (cost=1000.00..514086.40 rows=1027284 width=37) (actual time=6.777..61558.272 rows=1010315 loops=1)
>    Workers Planned: 2
>    Workers Launched: 2
>    ->  Parallel Seq Scan on iot_data_0  (cost=0.00..410358.00 rows=428035 width=37) (actual time=1.152..61414.483
rows=336772loops=3)
 

For whatever reason, your storage/OS seem to be handling parallel reads poorly.
I would SET max_parallel_workers_per_gather=0 and retest (but also look into
improving the storage).

Also, it's not required, but I think a typical partitioning schema would have
an index on the column being partitioned.  I see you have an index on
iot_data(metadata,lower(data)), so I still wonder whether you'd have better
results partitioned on metadata, or otherwise maybe adding an index on
"device".  But I don't know what your typical queries are.

> PG9.6
> postgres=# explain analyze select * from iot_data where device=51;
>                                                        QUERY PLAN
>
-------------------------------------------------------------------------------------------------------------------------
>  Seq Scan on iot_data  (cost=0.00..2083334.60 rows=976667 width=37) (actual time=21.922..16753.492 rows=1010315
loops=1)

-- 
Justin

On Tue, 10 Mar 2020 at 02:08, Mariel Cherkassky
<mariel.cherkassky@gmail.com> wrote:

> PG12 - 3 PARTITIONS
>
>                                                                      QUERY PLAN
>
----------------------------------------------------------------------------------------------------------------------------------------------------
>  Gather  (cost=1002.26..1563512.35 rows=10 width=44) (actual time=22306.091..22309.209 rows=0 loops=1)
>    Workers Planned: 2
>    Workers Launched: 2
>    ->  Hash Join  (cost=2.26..1562511.35 rows=4 width=44) (actual time=22299.412..22299.413 rows=0 loops=3)
>          Hash Cond: (da_2.device = de.id)
>          ->  Parallel Append  (cost=0.00..1562506.90 rows=814 width=37) (actual time=22299.411..22299.411 rows=0
loops=3)
>                ->  Parallel Seq Scan on iot_data_2 da_2  (cost=0.00..584064.14 rows=305 width=37) (actual
time=9076.535..9076.535rows=0 loops=3)
 
>                      Filter: ((metadata = 50) AND (lower(data) ~~ '50'::text))
>                      Rows Removed by Filter: 12460009
>                ->  Parallel Seq Scan on iot_data_1 da_1  (cost=0.00..504948.69 rows=262 width=36) (actual
time=10296.751..10296.751rows=0 loops=2)
 
>                      Filter: ((metadata = 50) AND (lower(data) ~~ '50'::text))
>                      Rows Removed by Filter: 16158316
>                ->  Parallel Seq Scan on iot_data_0 da  (cost=0.00..473490.00 rows=247 width=37) (actual
time=19075.081..19075.081rows=0 loops=1)
 
>                      Filter: ((metadata = 50) AND (lower(data) ~~ '50'::text))
>                      Rows Removed by Filter: 30303339
>          ->  Hash  (cost=2.25..2.25 rows=1 width=7) (never executed)
>                ->  Seq Scan on iot_device de  (cost=0.00..2.25 rows=1 width=7) (never executed)
>                      Filter: (name = '50a'::text)
>  Planning Time: 30.429 ms
>  Execution Time: 22309.364 ms
> (20 rows)

From what I can work out, the DDL you used here is:

-- you didn't seem to specify the DDL for iot_device, so I used:
create table iot_device (
id bigint primary key,
name text not null
);

insert into iot_device select x,x::Text || 'a' from generate_Series(1,100) x;

create table iot_data(id serial ,data text,metadata bigint,device
bigint references iot_device(id),primary key(id,device)) partition by
hash(device);
create table iot_data_0 partition of iot_data for values with (MODULUS
3, remainder 0);
create table iot_data_1 partition of iot_data for values with (MODULUS
3, remainder 1);
create table iot_data_2 partition of iot_data for values with (MODULUS
3, remainder 2);

insert into iot_data select
generate_series(1,10000000),random()*10,random()*254,random()*99+1;
create index on iot_data(metadata,lower(data));
vacuum analyze iot_data;

In which case, you're getting a pretty different plan than I am. (I
admit that I only tried on current master and not PG12.2, however, I
see no reason that PG12.2 shouldn't produce the same plan)

I get:

# explain analyze select * from iot_data da,iot_device de where
de.name in ('50a') and de.id = da.device and da.metadata=50 and
lower(da.data) like '50';

  QUERY PLAN

------------------------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop  (cost=0.56..28.04 rows=1 width=49) (actual
time=0.058..0.058 rows=0 loops=1)
   Join Filter: (da.device = de.id)
   ->  Seq Scan on iot_device de  (cost=0.00..2.25 rows=1 width=11)
(actual time=0.013..0.016 rows=1 loops=1)
         Filter: (name = '50a'::text)
         Rows Removed by Filter: 99
   ->  Append  (cost=0.56..25.76 rows=3 width=38) (actual
time=0.040..0.040 rows=0 loops=1)
         ->  Index Scan using iot_data_0_metadata_lower_idx on
iot_data_0 da_1  (cost=0.56..8.58 rows=1 width=38) (actual
time=0.020..0.020 rows=0 loops=1)
               Index Cond: ((metadata = 50) AND (lower(data) = '50'::text))
               Filter: (lower(data) ~~ '50'::text)
         ->  Index Scan using iot_data_1_metadata_lower_idx on
iot_data_1 da_2  (cost=0.56..8.58 rows=1 width=38) (actual
time=0.010..0.010 rows=0 loops=1)
               Index Cond: ((metadata = 50) AND (lower(data) = '50'::text))
               Filter: (lower(data) ~~ '50'::text)
         ->  Index Scan using iot_data_2_metadata_lower_idx on
iot_data_2 da_3  (cost=0.56..8.58 rows=1 width=38) (actual
time=0.009..0.009 rows=0 loops=1)
               Index Cond: ((metadata = 50) AND (lower(data) = '50'::text))
               Filter: (lower(data) ~~ '50'::text)
 Planning Time: 0.280 ms
 Execution Time: 0.094 ms
(17 rows)

Are you certain that you added an index on iot_data (metadata, lower(data)); ?