Thread: 9.6 query slower than 9.5.3

9.6 query slower than 9.5.3

From

Adam Brusselback

Date:

17 June 2016, 04:56:32

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'

Re: 9.6 query slower than 9.5.3

From

Tom Lane

Date:

17 June 2016, 05:04:29

Adam Brusselback <adambrusselback@gmail.com> writes:
> 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.

The rowcount estimates in 9.6 seem way off.  Did you ANALYZE the tables
after loading them into 9.6?  Maybe you forgot some statistics target
settings?

If it's not that, I wonder whether the misestimates are connected to the
foreign-key-based estimation feature.  Are there any FKs on the tables
involved?  May we see the table schemas?

            regards, tom lane

Re: 9.6 query slower than 9.5.3

From

Adam Brusselback

Date:

17 June 2016, 05:10:00

I analyzed all tables involved after loading, and also while trying to diagnose this issue.

I have the same statistics target settings on both servers.

Here are the schemas for the tables:

On Thu, Jun 16, 2016 at 10:04 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Adam Brusselback <adambrusselback@gmail.com> writes:
> 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.

The rowcount estimates in 9.6 seem way off. Did you ANALYZE the tables
after loading them into 9.6? Maybe you forgot some statistics target
settings?

If it's not that, I wonder whether the misestimates are connected to the
foreign-key-based estimation feature. Are there any FKs on the tables
involved? May we see the table schemas?

regards, tom lane

Re: 9.6 query slower than 9.5.3

From

Adam Brusselback

Date:

17 June 2016, 05:14:26

Gah, hit send too soon...

CREATE TEMPORARY TABLE _claims_to_process ( claim_id uuid, starting_state enum.claim_state );

CREATE TABLE claim_product

(

claim_product_id uuid NOT NULL DEFAULT gen_random_uuid(),

claim_id uuid NOT NULL,

product_id uuid NOT NULL,

uom_type_id uuid NOT NULL,

rebate_requested_quantity numeric NOT NULL,

rebate_requested_rate numeric NOT NULL,

rebate_allowed_quantity numeric NOT NULL,

rebate_allowed_rate numeric NOT NULL,

distributor_company_id uuid,

location_company_id uuid,

contract_item_id uuid,

claimant_contract_name character varying, -- NOT SOURCE OF TRUTH; Client defined. - Yesod

resolve_date date NOT NULL, -- FIXME: TENTATIVE NAME; Does not mean contract_item_id resolve date. - Yesod

rebate_calculated_rate numeric NOT NULL,

CONSTRAINT claim_product_pkey PRIMARY KEY (claim_product_id),

CONSTRAINT claim_product_claim_id_fkey FOREIGN KEY (claim_id)

REFERENCES claim (claim_id) MATCH SIMPLE

ON UPDATE NO ACTION ON DELETE NO ACTION,

CONSTRAINT claim_product_contract_item_id_fkey FOREIGN KEY (contract_item_id)

REFERENCES contract_item (contract_item_id) MATCH SIMPLE

ON UPDATE NO ACTION ON DELETE NO ACTION,

CONSTRAINT claim_product_distributor_company_id_fkey FOREIGN KEY (distributor_company_id)

REFERENCES company (company_id) MATCH SIMPLE

ON UPDATE NO ACTION ON DELETE NO ACTION,

CONSTRAINT claim_product_location_company_id_fkey FOREIGN KEY (location_company_id)

REFERENCES company (company_id) MATCH SIMPLE

ON UPDATE NO ACTION ON DELETE NO ACTION,

CONSTRAINT claim_product_product_id_fkey FOREIGN KEY (product_id)

REFERENCES product (product_id) MATCH SIMPLE

ON UPDATE NO ACTION ON DELETE NO ACTION,

CONSTRAINT claim_product_uom_type_id_fkey FOREIGN KEY (uom_type_id)

REFERENCES uom_type (uom_type_id) MATCH SIMPLE

ON UPDATE NO ACTION ON DELETE NO ACTION

)

WITH (

OIDS=FALSE

);

ALTER TABLE claim_product

OWNER TO root;

GRANT ALL ON TABLE claim_product TO root;

COMMENT ON COLUMN claim_product.claimant_contract_name IS 'NOT SOURCE OF TRUTH; Client defined. - Yesod';

COMMENT ON COLUMN claim_product.resolve_date IS 'FIXME: TENTATIVE NAME; Does not mean contract_item_id resolve date. - Yesod';

-- Index: idx_claim_product_claim_id

-- DROP INDEX idx_claim_product_claim_id;

CREATE INDEX idx_claim_product_claim_id

ON claim_product

USING btree

(claim_id);

-- Index: idx_claim_product_contract_item_id

-- DROP INDEX idx_claim_product_contract_item_id;

CREATE INDEX idx_claim_product_contract_item_id

ON claim_product

USING btree

(contract_item_id);

-- Trigger: claim_product_iud_trigger on claim_product

-- DROP TRIGGER claim_product_iud_trigger ON claim_product;

CREATE TRIGGER claim_product_iud_trigger

AFTER INSERT OR UPDATE OR DELETE

ON claim_product

FOR EACH ROW

EXECUTE PROCEDURE gosimple.claim_product_on_iud();

-- Trigger: claim_product_statement_trigger on claim_product

-- DROP TRIGGER claim_product_statement_trigger ON claim_product;

CREATE TRIGGER claim_product_statement_trigger

AFTER INSERT OR UPDATE OR DELETE

ON claim_product

FOR EACH STATEMENT

EXECUTE PROCEDURE gosimple.claim_product_statement_refresh_trigger();

CREATE TABLE claim_product_reason_code

(

claim_product_reason_code_id uuid NOT NULL DEFAULT gen_random_uuid(),

claim_product_id uuid NOT NULL,

claim_reason_type enum.claim_reason_type NOT NULL,

claim_reason_code enum.claim_reason_code NOT NULL,

claim_reason_note character varying,

active_range tstzrange NOT NULL DEFAULT tstzrange(now(), NULL::timestamp with time zone),

CONSTRAINT claim_product_reason_code_pkey PRIMARY KEY (claim_product_reason_code_id),

CONSTRAINT claim_product_reason_code_claim_product_id_fkey FOREIGN KEY (claim_product_id)

REFERENCES claim_product (claim_product_id) MATCH SIMPLE

ON UPDATE NO ACTION ON DELETE NO ACTION,

CONSTRAINT claim_product_reason_code_active_range_excl EXCLUDE

USING gist (gosimple.uuid_to_bytea(claim_product_id) WITH =, gosimple.enum_to_oid('enum'::text, 'claim_reason_type'::text, claim_reason_type) WITH =, gosimple.enum_to_oid('enum'::text, 'claim_reason_code'::text, claim_reason_code) WITH =, active_range WITH &&),

CONSTRAINT claim_product_reason_code_excl EXCLUDE

USING gist (gosimple.uuid_to_bytea(claim_product_id) WITH =, (

CASE

WHEN upper(active_range) IS NULL THEN 'infinity'::text

ELSE NULL::text

END) WITH =, gosimple.enum_to_oid('enum'::text, 'claim_reason_type'::text, claim_reason_type) WITH <>),

CONSTRAINT claim_product_reason_code_unique UNIQUE (claim_product_id, claim_reason_type, claim_reason_code, active_range)

)

WITH (

OIDS=FALSE

);

ALTER TABLE claim_product_reason_code

OWNER TO root;

GRANT ALL ON TABLE claim_product_reason_code TO root;

-- Index: claim_product_reason_code_active_range_idx

-- DROP INDEX claim_product_reason_code_active_range_idx;

CREATE INDEX claim_product_reason_code_active_range_idx

ON claim_product_reason_code

USING btree

(claim_product_id, claim_reason_type)

WHERE upper_inf(active_range);

-- Index: claim_product_reason_code_not_pend_unique

-- DROP INDEX claim_product_reason_code_not_pend_unique;

CREATE UNIQUE INDEX claim_product_reason_code_not_pend_unique

ON claim_product_reason_code

USING btree

(claim_product_id, claim_reason_type)

WHERE upper(active_range) IS NULL AND claim_reason_type <> 'PEND'::enum.claim_reason_type;

-- Trigger: claim_product_reason_code_insert_trigger on claim_product_reason_code

-- DROP TRIGGER claim_product_reason_code_insert_trigger ON claim_product_reason_code;

CREATE TRIGGER claim_product_reason_code_insert_trigger

BEFORE INSERT

ON claim_product_reason_code

FOR EACH ROW

EXECUTE PROCEDURE gosimple.update_claim_product_reason_code_active_range();

On Thu, Jun 16, 2016 at 10:09 PM, Adam Brusselback <adambrusselback@gmail.com> wrote:

I analyzed all tables involved after loading, and also while trying to diagnose this issue.

I have the same statistics target settings on both servers.

Here are the schemas for the tables:

On Thu, Jun 16, 2016 at 10:04 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Adam Brusselback <adambrusselback@gmail.com> writes:
> 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.

The rowcount estimates in 9.6 seem way off. Did you ANALYZE the tables
after loading them into 9.6? Maybe you forgot some statistics target
settings?

If it's not that, I wonder whether the misestimates are connected to the
foreign-key-based estimation feature. Are there any FKs on the tables
involved? May we see the table schemas?

regards, tom lane

Re: 9.6 query slower than 9.5.3

From

Tom Lane

Date:

17 June 2016, 05:45:10

Adam Brusselback <adambrusselback@gmail.com> writes:
> Gah, hit send too soon...

Hm, definitely a lot of foreign keys in there.  Do the estimates get
better (or at least closer to 9.5) if you do
"set enable_fkey_estimates = off"?

            regards, tom lane

Re: 9.6 query slower than 9.5.3

From

Adam Brusselback

Date:

17 June 2016, 06:36:28

Alright with that off I get:

'Nested Loop Anti Join (cost=25.76..21210.81 rows=16684 width=106) (actual time=0.688..249.585 rows=26994 loops=1)'

' -> Hash Join (cost=25.34..7716.95 rows=21906 width=106) (actual time=0.671..124.663 rows=28467 loops=1)'

' Hash Cond: (cp.claim_id = x.claim_id)'

' -> Seq Scan on claim_product cp (cost=0.00..6714.76 rows=202076 width=106) (actual time=0.016..55.230 rows=202076 loops=1)'

' -> Hash (cost=14.04..14.04 rows=904 width=16) (actual time=0.484..0.484 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.013..0.235 rows=904 loops=1)'

' -> Index Only Scan using claim_product_reason_code_active_range_idx on claim_product_reason_code r (cost=0.42..0.61 rows=1 width=16) (actual time=0.004..0.004 rows=0 loops=28467)'

' Index Cond: (claim_product_id = cp.claim_product_id)'

' Filter: (claim_reason_type = ANY ('{REJECT,OVERRIDE,RECALC}'::enum.claim_reason_type[]))'

' Rows Removed by Filter: 1'

' Heap Fetches: 27031'

'Planning time: 0.984 ms'

'Execution time: 253.976 ms'

Way better.

Re: 9.6 query slower than 9.5.3

From

Tom Lane

Date:

17 June 2016, 06:57:41

Adam Brusselback <adambrusselback@gmail.com> writes:
> Alright with that off I get:
> ...
> Way better.

OK, that confirms the suspicion that beta1's FK-join-estimation logic
is the culprit here.  We had already decided that that logic is broken,
and there's a rewrite in progress:
https://www.postgresql.org/message-id/15245.1466031608%40sss.pgh.pa.us

I wonder though whether the rewrite will fix your example.  Could you
either make some test data available, or try HEAD + aforesaid patch
to see if it behaves sanely on your data?

            regards, tom lane

Re: 9.6 query slower than 9.5.3

From

Adam Brusselback

Date:

17 June 2016, 07:07:21

It'd be really hard to get a test dataset together I think, so I suppose i'll learn how to compile Postgres. Will let you know how that goes.

Re: 9.6 query slower than 9.5.3

From

Adam Brusselback

Date:

17 June 2016, 18:18:24

I finally managed to get it compiled, patched, and working. It gave the same plan with the same estimates as when I turned fkey_estimates off.

I was wondering if I did things properly though, as i don't see the enable_fkey_estimates GUC any more. Was it removed?

Re: 9.6 query slower than 9.5.3

From

Tom Lane

Date:

17 June 2016, 18:22:16

Adam Brusselback <adambrusselback@gmail.com> writes:
> I finally managed to get it compiled, patched, and working.  It gave the
> same plan with the same estimates as when I turned fkey_estimates off.

OK, well, at least it's not making things worse ;-).  But I think that
this estimation method isn't very helpful for antijoin cases anyway.

> I was wondering if I did things properly though, as i don't see the
> enable_fkey_estimates GUC any more. Was it removed?

Yes, that was only intended for debugging, and the consensus was that
it probably shouldn't have been committed in the first place.

Thanks for taking the trouble to check this!

            regards, tom lane