Regression in query optimizer when upgrading from 9.4.5 to 9.5.2?

Hello,

We’re trying to debug a performance issue affecting our staging database, and we’ve narrowed it down to a difference in the query optimizer in 9.5.2. Upgrading to 9.5 is important for us because we need the ability to import foreign schemas.

This is the query we’re running:

CREATE TEMP TABLE tmp_joined_transactions_9gkgptn5xcp9 ( transaction_id integer PRIMARY KEY );

INSERT INTO tmp_joined_transactions_9gkgptn5xcp9 (transaction_id)
SELECT DISTINCT ON ("transactions_transaction"."id") "transactions_transaction"."id"
FROM "transactions_transaction" , "tmp_joined_transactions_75chlsokrsev"
WHERE (NOT ("transactions_transaction"."id"
IN (SELECT U0."id" AS Col1
FROM "transactions_transaction" U0
LEFT OUTER JOIN "transactions_commission" U1
ON ( U0."id" = U1."transaction_id" )
WHERE U1."id" IS NULL))
AND "transactions_transaction"."date_created" >= '2010-01-01'::date
AND "transactions_transaction"."date_created" <= '2015-12-31'::date
AND "transactions_transaction"."deal_status" IN (1)
AND (transactions_transaction.id = tmp_joined_transactions_75chlsokrsev.transaction_id))
ORDER BY "transactions_transaction"."id" ASC;

And this is the EXPLAIN ANALYZE output in 9.5.2:

Insert on tmp_joined_transactions_9gkgptn5xcp9 (cost=42111.29..42991.60 rows=1 width=4) (actual time=470236.029..470236.029 rows=0 loops=1)
-> Unique (cost=42111.29..42991.59 rows=1 width=4) (actual time=1109.636..470222.609 rows=4652 loops=1)
-> Nested Loop (cost=42111.29..42991.59 rows=1 width=4) (actual time=1109.635..470219.259 rows=4652 loops=1)
Join Filter: (transactions_transaction.id = tmp_joined_transactions_75chlsokrsev.transaction_id)
Rows Removed by Join Filter: 1153472704
-> Index Only Scan using tmp_joined_transactions_75chlsokrsev_pkey on tmp_joined_transactions_75chlsokrsev (cost=0.28..224.61 rows=5355 width=4) (actual time=0.016..4.829 rows=4652 loops=1)
Heap Fetches: 4652
-> Materialize (cost=42111.01..42686.66 rows=1 width=4) (actual time=0.240..51.639 rows=247953 loops=4652)
-> Bitmap Heap Scan on transactions_transaction (cost=42111.01..42686.65 rows=1 width=4) (actual time=1109.580..1238.034 rows=247953 loops=1)
Recheck Cond: ((date_created >= '2010-01-01'::date) AND (date_created <= '2015-12-31'::date))
Filter: ((NOT (hashed SubPlan 1)) AND (deal_status = 1))
Rows Removed by Filter: 21068
Heap Blocks: exact=8073
-> Bitmap Index Scan on transactions_transaction_c69e55a4 (cost=0.00..18.02 rows=161 width=0) (actual time=20.153..20.153 rows=269021 loops=1)
Index Cond: ((date_created >= '2010-01-01'::date) AND (date_created <= '2015-12-31'::date))
SubPlan 1
-> Hash Right Join (cost=8799.57..42092.98 rows=1 width=4) (actual time=852.012..1086.671 rows=3395 loops=1)
Hash Cond: (u1.transaction_id = u0.id)
Filter: (u1.id IS NULL)
Rows Removed by Filter: 995248
-> Seq Scan on transactions_commission u1 (cost=0.00..27020.63 rows=1039763 width=8) (actual time=0.003..221.750 rows=1039763 loops=1)
-> Hash (cost=8395.92..8395.92 rows=32292 width=4) (actual time=153.984..153.984 rows=272663 loops=1)
Buckets: 131072 (originally 32768) Batches: 4 (originally 1) Memory Usage: 3425kB
-> Seq Scan on transactions_transaction u0 (cost=0.00..8395.92 rows=32292 width=4) (actual time=0.003..71.988 rows=272663 loops=1)
Planning time: 0.410 ms
Execution time: 470237.400 ms

And this is the EXPLAIN ANALYZE output in 9.4.5:

Insert on tmp_joined_transactions_9gkgptn5xcp9 (cost=88544.31..88576.62 rows=2154 width=4) (actual time=1356.065..1356.065 rows=0 loops=1)
-> Unique (cost=88544.31..88555.08 rows=2154 width=4) (actual time=1347.480..1350.548 rows=4715 loops=1)
-> Sort (cost=88544.31..88549.70 rows=2154 width=4) (actual time=1347.477..1348.432 rows=4715 loops=1)
Sort Key: transactions_transaction.id
Sort Method: quicksort Memory: 414kB
-> Hash Join (cost=72700.01..88425.06 rows=2154 width=4) (actual time=1107.077..1345.650 rows=4715 loops=1)
Hash Cond: (transactions_transaction.id = tmp_joined_transactions_75chlsokrsev.transaction_id)
-> Seq Scan on transactions_transaction (cost=72565.61..87199.11 rows=122287 width=4) (actual time=1104.855..1269.783 rows=251736 loops=1)
Filter: ((NOT (hashed SubPlan 1)) AND (date_created >= '2010-01-01'::date) AND (date_created <= '2015-12-31'::date) AND (deal_status = 1))
Rows Removed by Filter: 34441
SubPlan 1
-> Hash Right Join (cost=16466.94..72565.61 rows=1 width=4) (actual time=887.763..1103.391 rows=3551 loops=1)
Hash Cond: (u1.transaction_id = u0.id)
Filter: (u1.id IS NULL)
Rows Removed by Filter: 1047414
-> Seq Scan on transactions_commission u1 (cost=0.00..28019.85 rows=1073685 width=8) (actual time=0.004..360.549 rows=1072675 loops=1)
-> Hash (cost=11771.75..11771.75 rows=286175 width=4) (actual time=167.675..167.675 rows=286177 loops=1)
Buckets: 16384 Batches: 4 Memory Usage: 2528kB
-> Seq Scan on transactions_transaction u0 (cost=0.00..11771.75 rows=286175 width=4) (actual time=0.002..84.517 rows=286177 loops=1)
-> Hash (cost=71.40..71.40 rows=5040 width=4) (actual time=2.202..2.202 rows=4715 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 166kB
-> Seq Scan on tmp_joined_transactions_75chlsokrsev (cost=0.00..71.40 rows=5040 width=4) (actual time=0.009..0.983 rows=4715 loops=1)
Planning time: 0.448 ms
Execution time: 1356.648 ms

The query is slower in 9.5.2 by several orders of magnitude (1300 ms vs 470000 ms).

Does anyone know if there is a way to modify our query to guide the query optimizer back in the right direction?

Thank you for your assistance,
Markus Erdmann