9.6 query slower than 9.5.3

From: Adam Brusselback <adambrusselback(at)gmail(dot)com>
To: pgsql-performance(at)postgresql(dot)org
Subject: 9.6 query slower than 9.5.3
Date: 2016-06-17 01:56:21
Message-ID: CAMjNa7eYj3O2K5WxVAmMmYVUh_XpvS4db0LSKxd-kk_ZgaMitg@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: 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'

Responses

Browse pgsql-performance by date

  From Date Subject
Next Message Tom Lane 2016-06-17 02:04:25 Re: 9.6 query slower than 9.5.3
Previous Message David G. Johnston 2016-06-16 15:53:34 Re: Index not used