9.6 query slower than 9.5.3 - Mailing list pgsql-performance

From Adam Brusselback
Subject 9.6 query slower than 9.5.3
Date
Msg-id CAMjNa7eYj3O2K5WxVAmMmYVUh_XpvS4db0LSKxd-kk_ZgaMitg@mail.gmail.com
Whole thread Raw
Responses Re: 9.6 query slower than 9.5.3
List pgsql-performance
Hey all, testing out 9.6 beta 1 right now on Debian 8.5.

I have a query that is much slower on 9.6 than 9.5.3.

As a side note, when I explain analyze instead of just executing the query it takes more than 2x as long to run. I have tried looking for info on that online but have not found any.  Anyone know the reason for that?

The data is very close between the two servers, one is my production system so the only difference is slightly more added today since I set up the 9.6 server last night.

The query in question is here: 
SELECT cp.claim_id
, cp.claim_product_id
, cp.product_id
, cp.uom_type_id
, cp.rebate_requested_quantity
, cp.rebate_requested_rate
, cp.rebate_allowed_quantity
, cp.rebate_allowed_rate
, cp.distributor_company_id
, cp.resolve_date
FROM claim_product cp
INNER JOIN _claims_to_process x
ON cp.claim_id = x.claim_id
WHERE NOT EXISTS ( 
SELECT 1
FROM claim_product_reason_code r
WHERE r.claim_product_id = cp.claim_product_id
AND r.claim_reason_type = ANY (ARRAY['REJECT'::enum.claim_reason_type, 'OVERRIDE'::enum.claim_reason_type, 'RECALC'::enum.claim_reason_type])
AND upper_inf(r.active_range)
);

The query plan on 9.6 is here (disabled parallelism):
'Nested Loop  (cost=17574.63..30834.02 rows=1 width=106) (actual time=241.934..40332.190 rows=26994 loops=1)'
'  Join Filter: (cp.claim_id = x.claim_id)'
'  Rows Removed by Join Filter: 92335590'
'  ->  Hash Anti Join  (cost=17574.63..30808.68 rows=1 width=106) (actual time=173.742..586.805 rows=102171 loops=1)'
'        Hash Cond: (cp.claim_product_id = r.claim_product_id)'
'        ->  Seq Scan on claim_product cp  (cost=0.00..6714.76 rows=202076 width=106) (actual time=0.028..183.376 rows=202076 loops=1)'
'        ->  Hash  (cost=16972.49..16972.49 rows=48171 width=16) (actual time=173.436..173.436 rows=99905 loops=1)'
'              Buckets: 131072 (originally 65536)  Batches: 1 (originally 1)  Memory Usage: 5708kB'
'              ->  Bitmap Heap Scan on claim_product_reason_code r  (cost=4398.71..16972.49 rows=48171 width=16) (actual time=25.278..127.540 rows=99905 loops=1)'
'                    Recheck Cond: ((claim_reason_type = ANY ('{REJECT,OVERRIDE,RECALC}'::enum.claim_reason_type[])) AND upper_inf(active_range))'
'                    Heap Blocks: exact=10067'
'                    ->  Bitmap Index Scan on claim_product_reason_code_active_range_idx  (cost=0.00..4386.67 rows=48171 width=0) (actual time=23.174..23.174 rows=99905 loops=1)'
'                          Index Cond: (claim_reason_type = ANY ('{REJECT,OVERRIDE,RECALC}'::enum.claim_reason_type[]))'
'  ->  Seq Scan on _claims_to_process x  (cost=0.00..14.04 rows=904 width=16) (actual time=0.005..0.182 rows=904 loops=102171)'
'Planning time: 1.934 ms'
'Execution time: 40337.858 ms'

The 9.5.3 plan is here:
'Hash Anti Join  (cost=19884.53..39281.57 rows=30681 width=106) (actual time=848.791..978.036 rows=27354 loops=1)'
'  Hash Cond: (cp.claim_product_id = r.claim_product_id)'
'  ->  Nested Loop  (cost=0.42..17990.36 rows=41140 width=106) (actual time=0.132..106.333 rows=28775 loops=1)'
'        ->  Seq Scan on _claims_to_process x  (cost=0.00..27.00 rows=1700 width=16) (actual time=0.037..0.465 rows=923 loops=1)'
'        ->  Index Scan using idx_claim_product_claim_id on claim_product cp  (cost=0.42..10.33 rows=24 width=106) (actual time=0.015..0.093 rows=31 loops=923)'
'              Index Cond: (claim_id = x.claim_id)'
'  ->  Hash  (cost=19239.13..19239.13 rows=51599 width=16) (actual time=848.263..848.263 rows=100024 loops=1)'
'        Buckets: 131072 (originally 65536)  Batches: 1 (originally 1)  Memory Usage: 5713kB'
'        ->  Bitmap Heap Scan on claim_product_reason_code r  (cost=6240.64..19239.13 rows=51599 width=16) (actual time=31.505..782.799 rows=100024 loops=1)'
'              Recheck Cond: ((claim_reason_type = ANY ('{REJECT,OVERRIDE,RECALC}'::enum.claim_reason_type[])) AND upper_inf(active_range))'
'              Heap Blocks: exact=6261'
'              ->  Bitmap Index Scan on claim_product_reason_code_active_range_idx  (cost=0.00..6227.74 rows=51599 width=0) (actual time=30.231..30.231 rows=100051 loops=1)'
'                    Index Cond: (claim_reason_type = ANY ('{REJECT,OVERRIDE,RECALC}'::enum.claim_reason_type[]))'
'Planning time: 1.691 ms'
'Execution time: 982.667 ms'


Just for fun I set enable_nestloop=false on 9.6 and this is the plan I get:
'Hash Join  (cost=17599.97..30834.04 rows=1 width=106) (actual time=108.892..349.885 rows=26994 loops=1)'
'  Hash Cond: (cp.claim_id = x.claim_id)'
'  ->  Hash Anti Join  (cost=17574.63..30808.68 rows=1 width=106) (actual time=107.464..316.527 rows=102171 loops=1)'
'        Hash Cond: (cp.claim_product_id = r.claim_product_id)'
'        ->  Seq Scan on claim_product cp  (cost=0.00..6714.76 rows=202076 width=106) (actual time=0.011..61.230 rows=202076 loops=1)'
'        ->  Hash  (cost=16972.49..16972.49 rows=48171 width=16) (actual time=107.315..107.315 rows=99905 loops=1)'
'              Buckets: 131072 (originally 65536)  Batches: 1 (originally 1)  Memory Usage: 5708kB'
'              ->  Bitmap Heap Scan on claim_product_reason_code r  (cost=4398.71..16972.49 rows=48171 width=16) (actual time=23.478..68.644 rows=99905 loops=1)'
'                    Recheck Cond: ((claim_reason_type = ANY ('{REJECT,OVERRIDE,RECALC}'::enum.claim_reason_type[])) AND upper_inf(active_range))'
'                    Heap Blocks: exact=10067'
'                    ->  Bitmap Index Scan on claim_product_reason_code_active_range_idx  (cost=0.00..4386.67 rows=48171 width=0) (actual time=21.475..21.475 rows=99905 loops=1)'
'                          Index Cond: (claim_reason_type = ANY ('{REJECT,OVERRIDE,RECALC}'::enum.claim_reason_type[]))'
'  ->  Hash  (cost=14.04..14.04 rows=904 width=16) (actual time=0.937..0.937 rows=904 loops=1)'
'        Buckets: 1024  Batches: 1  Memory Usage: 51kB'
'        ->  Seq Scan on _claims_to_process x  (cost=0.00..14.04 rows=904 width=16) (actual time=0.022..0.442 rows=904 loops=1)'
'Planning time: 1.475 ms'
'Execution time: 353.958 ms'


pgsql-performance by date:

Previous
From: "David G. Johnston"
Date:
Subject: Re: Index not used
Next
From: Tom Lane
Date:
Subject: Re: 9.6 query slower than 9.5.3