Performance regressions found using sqlfuzz

Hello,

Thanks for the feedback so far! Continue with the previous report, we
sharing another four interesting cases that SQLFuzz discovered.
(previous discussion:
https://www.postgresql.org/message-id/flat/BN6PR07MB3409EE6CAAF8CCF43820AFB9EE670%40BN6PR07MB3409.namprd07.prod.outlook.com#acc68f0fbd8f0b207e162d2dd401d3e8
)

Here’s the time taken to execute four SQL queries on old (v9.5.16) and
newer version (v11.2) of PostgreSQL (in milliseconds):

+----------------------+--------+---------+---------+---------+
| | scale1 | scale10 | scale50 | scale300|
+----------------------+--------+---------+---------+---------+
| Case-5 (v9.5.16) | 39 | 183 | 1459 | 11125 |
| Case-5 (v11.2) | 73 | 620 | 4818 | 16956 |
+----------------------+--------+---------+---------+---------+
| Case-6 (v9.5.16) | 46 | 329 | 15096 | 10721 |
| Case-6 (v11.2) | 81 | 671 | 64808 | 26919 |
+----------------------+--------+---------+---------+---------+
| Case-7 (v9.5.16) | 19 | X | X | X |
| Case-7 (v11.2) | 46 | X | X | X |
+----------------------+--------+---------+---------+---------+
| Case-8 (v9.5.16) | 215 | 2108 | 10460 | 64959 |
| Case-8 (v11.2) | 449 | 3997 | 20246 | 130595 |
+----------------------+--------+---------+---------+---------+

For each regression, we share:
1) the associated query,
2) the commit that activated it,
3) our high-level analysis, and
4) query execution plans in old and new versions of PostgreSQL.

All these regressions are observed on the latest version. (v11.2 and
v9.5.16)

* You can download the queries at:
https://gts3.org/~/jjung/tpcc/case2.tar.gz

* You can reproduce the result by using the same setup that we described
before:
https://www.postgresql.org/message-id/BN6PR07MB3409922471073F2B619A8CA4EE640%40BN6PR07MB3409.namprd07.prod.outlook.com

- As Andrew mentioned before, we increased default work_mem to 128MB

Best regards,
Jinho Jung

#### QUERY 5

EXPLAIN ANALYZE
select
ref_0.c_zip as c0
from
public.customer as ref_0
where EXISTS (
select
ref_1.ol_d_id as c10
from
public.order_line as ref_1
where (ref_1.ol_o_id <> ref_0.c_d_id)
)

- Commit : 7ca25b7

- Our analysis: We believe newer version is slow when the number of rows in
the filter is small.

- Query execution plans:

[Old version]
Nested Loop Semi Join (cost=0.00..15317063263550.52 rows=1 width=10)
(actual time=0.019..10888.266 rows=9000000 loops=1)
Join Filter: (ref_1.ol_o_id <> ref_0.c_d_id)
Rows Removed by Join Filter: 11700000
-> Seq Scan on customer ref_0 (cost=0.00..770327.00 rows=9000000
width=14) (actual time=0.008..7541.944 rows=9000000 loops=1)
-> Materialize (cost=0.00..2813223.52 rows=90017568 width=4) (actual
time=0.000..0.000 rows=2 loops=9000000)
-> Seq Scan on order_line ref_1 (cost=0.00..2011503.68
rows=90017568 width=4) (actual time=0.005..0.007 rows=14 loops=1)
Planning time: 0.401 ms
Execution time: 11125.538 ms

[New version]
Nested Loop Semi Join (cost=0.00..3409260.89 rows=9000000 width=10)
(actual time=0.033..16732.988 rows=9000000 loops=1)
Join Filter: (ref_1.ol_o_id <> ref_0.c_d_id)
Rows Removed by Join Filter: 11700000
-> Seq Scan on customer ref_0 (cost=0.00..770327.00 rows=9000000
width=14) (actual time=0.017..2113.336 rows=9000000 loops=1)
-> Seq Scan on order_line ref_1 (cost=0.00..2011503.68 rows=90017568
width=4) (actual time=0.001..0.001 rows=2 loops=9000000)
Planning Time: 0.615 ms
Execution Time: 16956.115 ms

##### QUERY 6

select distinct
ref_0.h_data as c0,
ref_0.h_c_id as c1
from
public.history as ref_0
left join public.item as ref_1
on (ref_1.i_im_id < -1)
where ref_1.i_price is NULL

- Our analysis: We think that the 'merge sort' makes slow execution. We are
wondering why newer version applies external merge sort in this case.

- Commit: 3fc6e2d (big patch)

- Query execution plans:

[Old version]
HashAggregate (cost=1312274.26..1312274.27 rows=1 width=21) (actual
time=7288.727..10443.586 rows=9000000 loops=1)
Group Key: ref_0.h_data, ref_0.h_c_id
-> Nested Loop Left Join (cost=0.00..1312274.26 rows=1 width=21)
(actual time=26.965..2463.231 rows=9000000 loops=1)
Filter: (ref_1.i_price IS NULL)
-> Seq Scan on history ref_0 (cost=0.00..184795.61 rows=8999661
width=21) (actual time=0.347..795.936 rows=9000000 loops=1)
-> Materialize (cost=0.00..2521.05 rows=10 width=6) (actual
time=0.000..0.000 rows=0 loops=9000000)
-> Seq Scan on item ref_1 (cost=0.00..2521.00 rows=10
width=6) (actual time=26.610..26.610 rows=0 loops=1)
Filter: (i_im_id < '-1'::integer)
Rows Removed by Filter: 100000
Planning time: 1.538 ms
Execution time: 10721.259 ms

[New version]
Unique (cost=1312334.34..1312334.35 rows=1 width=21) (actual
time=21444.459..26651.868 rows=9000000 loops=1)
-> Sort (cost=1312334.34..1312334.35 rows=1 width=21) (actual
time=21444.457..25629.389 rows=9000000 loops=1)
Sort Key: ref_0.h_data, ref_0.h_c_id
Sort Method: external merge Disk: 285384kB
-> Nested Loop Left Join (cost=0.00..1312334.33 rows=1 width=21)
(actual time=21.328..2409.302 rows=9000000 loops=1)
Filter: (ref_1.i_price IS NULL)
-> Seq Scan on history ref_0 (cost=0.00..184800.06
rows=9000106 width=21) (actual time=0.320..734.376 rows=9000000 loops=1)
-> Materialize (cost=0.00..2521.05 rows=10 width=6) (actual
time=0.000..0.000 rows=0 loops=9000000)
-> Seq Scan on item ref_1 (cost=0.00..2521.00 rows=10
width=6) (actual time=21.000..21.001 rows=0 loops=1)
Filter: (i_im_id < '-1'::integer)
Rows Removed by Filter: 100000
Planning Time: 1.426 ms
Execution Time: 26919.635 ms

##### QUERY 7

select
ref_0.c_id as c0
from
public.customer as ref_0
where EXISTS (
select
ref_0.c_city as c0
from
public.order_line as ref_1
left join public.new_order as ref_2
on (ref_1.ol_supply_w_id = ref_2.no_w_id)
where (ref_1.ol_delivery_d > ref_0.c_since)
)

- Our analysis : Parallel execution seems a problem. We also want to ask
whether only one worker is intended behavior of Postgres because we think
parallel execution with less than two workers is not parallel.

- Another interesting finding: this query cannot be finished within one day
if we incrase the size of DB (e.g., from scale factor 1 to scale factor
10/50/300).

- Commit: 16be2fd

- Query execution plans:

[Old version]
Nested Loop Semi Join (cost=224.43..910152608046.08 rows=10000 width=4)
(actual time=2.619..18.042 rows=30000 loops=1)
Join Filter: (ref_1.ol_delivery_d > ref_0.c_since)
-> Seq Scan on customer ref_0 (cost=0.00..2569.00 rows=30000 width=12)
(actual time=0.003..4.530 rows=30000 loops=1)
-> Materialize (cost=224.43..48521498.97 rows=2406886812 width=8)
(actual time=0.000..0.000 rows=1 loops=30000)
-> Hash Left Join (cost=224.43..27085162.91 rows=2406886812
width=8) (actual time=2.612..2.612 rows=1 loops=1)
Hash Cond: (ref_1.ol_supply_w_id = ref_2.no_w_id)
-> Seq Scan on order_line ref_1 (cost=0.00..6711.48
rows=300148 width=12) (actual time=0.002..0.002 rows=1 loops=1)
-> Hash (cost=124.19..124.19 rows=8019 width=4) (actual
time=2.571..2.571 rows=8019 loops=1)
Buckets: 8192 Batches: 1 Memory Usage: 346kB
-> Seq Scan on new_order ref_2 (cost=0.00..124.19
rows=8019 width=4) (actual time=0.174..1.539 rows=8019 loops=1)
Planning time: 0.605 ms
Execution time: 19.045 ms

[New version]
Gather (cost=1224.43..672617098015.10 rows=10000 width=4) (actual
time=3.099..45.077 rows=30000 loops=1)
Workers Planned: 1
Workers Launched: 1
-> Nested Loop Semi Join (cost=224.43..672617096015.10 rows=5882
width=4) (actual time=2.307..38.258 rows=15000 loops=2)
Join Filter: (ref_1.ol_delivery_d > ref_0.c_since)
-> Parallel Seq Scan on customer ref_0 (cost=0.00..2445.47
rows=17647 width=12) (actual time=0.003..2.668 rows=15000 loops=2)
-> Hash Left Join (cost=224.43..27085162.91 rows=2406886812
width=8) (actual time=0.002..0.002 rows=1 loops=30000)
Hash Cond: (ref_1.ol_supply_w_id = ref_2.no_w_id)
-> Seq Scan on order_line ref_1 (cost=0.00..6711.48
rows=300148 width=12) (actual time=0.001..0.001 rows=1 loops=30000)
-> Hash (cost=124.19..124.19 rows=8019 width=4) (actual
time=2.211..2.211 rows=8019 loops=2)
Buckets: 8192 Batches: 1 Memory Usage: 346kB
-> Seq Scan on new_order ref_2 (cost=0.00..124.19
rows=8019 width=4) (actual time=0.086..1.179 rows=8019 loops=2)
Planning Time: 0.611 ms
Execution Time: 46.195 ms

##### QUERY 8

select
ref_0.ol_d_id as c0
from
public.order_line as ref_0
left join (
select
ref_1.ol_supply_w_id as c0,
ref_1.ol_d_id as c2
from
public.order_line as ref_1
where ref_1.ol_o_id < 1
) as subq_0
on (subq_0.c2 = ref_0.ol_o_id)
where EXISTS (
select
ref_2.o_ol_cnt as c0
from
public.oorder as ref_2
where
nullif(ref_2.o_d_id, subq_0.c0) is not NULL
);

- Commit: 0c2070c

- Our analysis : We are not sure about the root cause of this regression.
This might have to do with parallel execution.

- Query execution plans:

[Old version]
Nested Loop Semi Join (cost=3488355.85..210034755085.67 rows=245615461
width=4) (actual time=32830.372..62745.966 rows=90017507 loops=1)
Join Filter: (NULLIF(ref_2.o_d_id, ref_1.ol_supply_w_id) IS NOT NULL)
-> Hash Right Join (cost=3488355.85..9115461.16 rows=246849710 width=8)
(actual time=32829.980..48232.002 rows=90017507 loops=1)
Hash Cond: (ref_1.ol_d_id = ref_0.ol_o_id)
-> Index Scan using order_line_pkey on order_line ref_1
(cost=0.57..2076988.89 rows=8461 width=8) (actual time=5346.547..5346.547
rows=0 loops=1)
Index Cond: (ol_o_id < 1)
-> Hash (cost=2011503.68..2011503.68 rows=90017568 width=8)
(actual time=27466.438..27466.438 rows=90017507 loops=1)
Buckets: 4194304 Batches: 64 Memory Usage: 80798kB
-> Seq Scan on order_line ref_0 (cost=0.00..2011503.68
rows=90017568 width=8) (actual time=0.006..16821.719 rows=90017507 loops=1)
-> Materialize (cost=0.00..245157.00 rows=9000000 width=4) (actual
time=0.000..0.000 rows=1 loops=90017507)
-> Seq Scan on oorder ref_2 (cost=0.00..165000.00 rows=9000000
width=4) (actual time=0.377..0.377 rows=1 loops=1)
Planning time: 3.933 ms
Execution time: 64959.231 ms

[New version]
Gather (cost=8797140.37..153823591859.11 rows=264667229 width=4) (actual
time=27917.270..128050.059 rows=90017507 loops=1)
Workers Planned: 2
Workers Launched: 2
-> Nested Loop Semi Join (cost=8796140.37..153797124136.21
rows=110278012 width=4) (actual time=27911.016..109588.362 rows=30005836
loops=3)
Join Filter: (NULLIF(ref_2.o_d_id, ref_1.ol_supply_w_id) IS NOT
NULL)
-> Merge Left Join (cost=8796140.37..10646159.56 rows=110832173
width=8) (actual time=27910.620..33777.444 rows=30005836 loops=3)
Merge Cond: (ref_0.ol_o_id = ref_1.ol_d_id)
-> Sort (cost=6717742.99..6811511.29 rows=37507320 width=8)
(actual time=22427.383..25862.373 rows=30005836 loops=3)
Sort Key: ref_0.ol_o_id
Sort Method: external merge Disk: 534352kB
Worker 0: Sort Method: external merge Disk: 509888kB
Worker 1: Sort Method: external merge Disk: 541512kB
-> Parallel Seq Scan on order_line ref_0
(cost=0.00..1486401.20 rows=37507320 width=8) (actual time=0.025..14349.178
rows=30005836 loops=3)
-> Sort (cost=2078397.38..2078419.66 rows=8912 width=8)
(actual time=5483.221..5483.221 rows=0 loops=3)
Sort Key: ref_1.ol_d_id
Sort Method: quicksort Memory: 25kB
Worker 0: Sort Method: quicksort Memory: 25kB
Worker 1: Sort Method: quicksort Memory: 25kB
-> Index Scan using order_line_pkey on order_line
ref_1 (cost=0.57..2077812.68 rows=8912 width=8) (actual
time=5483.203..5483.203 rows=0 loops=3)
Index Cond: (ol_o_id < 1)
-> Seq Scan on oorder ref_2 (cost=0.00..165000.00 rows=9000000
width=4) (actual time=0.002..0.002 rows=1 loops=90017507)
Planning Time: 3.952 ms
Execution Time: 130595.467 ms

===================================
Following up with previous question
===================================

on-going discussion:
https://www.postgresql.org/message-id/flat/BN6PR07MB3409EE6CAAF8CCF43820AFB9EE670%40BN6PR07MB3409.namprd07.prod.outlook.com#acc68f0fbd8f0b207e162d2dd401d3e8

Hello Andres,

Could you please share your thoughts on QUERY 3?

The performance impact of this regression increases *linearly* on larger
databases. We concur with Andrew in that this is related to the lack of a
Materialize node and mis-costing of the Nested Loop Anti-Join.

We found more than 20 regressions related to this commit. We have shared
two illustrative examples (QUERIES 3A and 3B) below.

- Commit: 77cd477 (Enable parallel query by default.)

- Summary: Execution Time (milliseconds)

When we increased the scale-factor of TPC-C to 300 (~30 GB), this query ran
three times slower on v11 (24 seconds) in comparison to v9.5 (7 seconds).
We also found more than 15 regressions related to the same commit and share
a couple of them below.

+-----------------------+--------+---------+---------+-----------+
| | scale1 | scale10 | scale50 | scale 300 |
+-----------------------+--------+---------+---------+-----------+
| Query 3 (v9.5) | 28 | 248 | 1231 | 7265 |
| Query 3 (v11) | 74 | 677 | 3345 | 24581 |
+-----------------------+--------+---------+---------+-----------+
| Query 3A (v9.5) | 88 | 937 | 4721 | 27241 |
| Query 3A (v11) | 288 | 2822 | 13838 | 85081 |
+-----------------------+--------+---------+---------+-----------+
| Query 3B (v9.5) | 101 | 934 | 4824 | 29363 |
| Query 3B (v11) | 200 | 2331 | 12327 | 74110 |
+-----------------------+--------+---------+---------+-----------+

###### QUERY 3:

select
cast(ref_1.ol_i_id as int4) as c0
from
public.stock as ref_0
left join public.order_line as ref_1
on (ref_1.ol_number is not null)
where ref_1.ol_number is null

###### QUERY 3A:

select
ref_0.ol_delivery_d as c1
from
public.order_line as ref_0
where EXISTS (
select
ref_1.i_im_id as c0
from
public.item as ref_1
where ref_0.ol_d_id <= ref_1.i_im_id
)

Execution plan:

[OLD version]
Nested Loop Semi Join (cost=0.00..90020417940.08 rows=30005835 width=8)
(actual time=0.034..24981.895 rows=90017507 loops=1)
Join Filter: (ref_0.ol_d_id <= ref_1.i_im_id)
-> Seq Scan on order_line ref_0 (cost=0.00..2011503.04 rows=90017504
width=12) (actual time=0.022..7145.811 rows=90017507 loops=1)
-> Materialize (cost=0.00..2771.00 rows=100000 width=4) (actual
time=0.000..0.000 rows=1 loops=90017507)
-> Seq Scan on item ref_1 (cost=0.00..2271.00 rows=100000
width=4) (actual time=0.006..0.006 rows=1 loops=1)

Planning time: 0.290 ms
Execution time: 27241.239 ms

[NEW version]
Gather (cost=1000.00..88047487498.82 rows=30005835 width=8) (actual
time=0.265..82355.289 rows=90017507 loops=1)
Workers Planned: 2
Workers Launched: 2
-> Nested Loop Semi Join (cost=0.00..88044485915.32 rows=12502431
width=8) (actual time=0.033..68529.259 rows=30005836 loops=3)
Join Filter: (ref_0.ol_d_id <= ref_1.i_im_id)
-> Parallel Seq Scan on order_line ref_0 (cost=0.00..1486400.93
rows=37507293 width=12) (actual time=0.023..2789.901 rows=30005836 loops=3)
-> Seq Scan on item ref_1 (cost=0.00..2271.00 rows=100000
width=4) (actual time=0.001..0.001 rows=1 loops=90017507)

Planning Time: 0.319 ms
Execution Time: 85081.158 ms

###### QUERY 3B:

select
ref_0.ol_i_id as c0
from
public.order_line as ref_0
where EXISTS (
select
ref_0.ol_delivery_d as c0
from
public.order_line as ref_1
where ref_1.ol_d_id <= cast(nullif(ref_1.ol_o_id, ref_0.ol_i_id) as
int4))

Execution plan:

[OLD version]
Nested Loop Semi Join (cost=0.00..115638730740936.53 rows=30005835
width=4) (actual time=0.017..27009.302 rows=90017507 loops=1)
Join Filter: (ref_1.ol_d_id <= NULLIF(ref_1.ol_o_id, ref_0.ol_i_id))
Rows Removed by Join Filter: 11557
-> Seq Scan on order_line ref_0 (cost=0.00..2011503.04 rows=90017504
width=4) (actual time=0.009..7199.540 rows=90017507 loops=1)
-> Materialize (cost=0.00..2813221.56 rows=90017504 width=8) (actual
time=0.000..0.000 rows=1 loops=90017507)
-> Seq Scan on order_line ref_1 (cost=0.00..2011503.04
rows=90017504 width=8) (actual time=0.001..0.002 rows=14 loops=1)

Planning time: 0.252 ms
Execution time: 29363.737 ms

[NEW version]
Gather (cost=1000.00..84060490326155.39 rows=30005835 width=4) (actual
time=0.272..71712.491 rows=90017507 loops=1)
Workers Planned: 2
Workers Launched: 2
-> Nested Loop Semi Join (cost=0.00..84060487324571.89 rows=12502431
width=4) (actual time=0.046..60153.472 rows=30005836 loops=3)
Join Filter: (ref_1.ol_d_id <= NULLIF(ref_1.ol_o_id, ref_0.ol_i_id))
Rows Removed by Join Filter: 1717
-> Parallel Seq Scan on order_line ref_0 (cost=0.00..1486400.93
rows=37507293 width=4) (actual time=0.023..2819.361 rows=30005836 loops=3)
-> Seq Scan on order_line ref_1 (cost=0.00..2011503.04
rows=90017504 width=8) (actual time=0.001..0.001 rows=1 loops=90017507)

Planning Time: 0.334 ms
Execution Time: 74110.942 ms