Обсуждение: performance regression with 9.2
This query is a couple orders of magnitude slower the first result is 9.2.1, the second 9.1
Dave Cramer
dave.cramer(at)credativ(dot)ca
http://www.credativ.ca
=# explain analyze SELECT note_sets."id" AS t0_r0, note_sets."note_set_source_id" AS t0_r1, note_sets."parent_id" AS t0_r2, note_sets."business_entity_id" AS t0_r3, note_sets."created_at" AS t0_r4, note_sets."updated_at" AS t0_r5, note_sets."created_by" AS t0_r6, note_sets."updated_by" AS t0_r7, note_set_sources."id" AS t1_r0, note_set_sources."name" AS t1_r1, note_set_sources."code" AS t1_r2, note_set_sources."description" AS t1_r3, note_set_sources."status" AS t1_r4, note_set_sources."created_at" AS t1_r5, note_set_sources."updated_at" AS t1_r6, note_set_sources."created_by" AS t1_r7, note_set_sources."updated_by" AS t1_r8, notes."id" AS t2_r0, notes."note_set_id" AS t2_r1, notes."subject" AS t2_r2, notes."text" AS t2_r3, notes."status" AS t2_r4, notes."is_dissmissable" AS t2_r5, notes."is_home" AS t2_r6, notes."created_at" AS t2_r7, notes."updated_at" AS t2_r8, notes."created_by" AS t2_r9, notes."updated_by" AS t2_r10 FROM note_sets LEFT OUTER JOIN note_set_sources ON note_set_sources.id = note_sets.note_set_source_id LEFT OUTER JOIN notes ON notes.note_set_id = note_sets.id AND notes."status" = E'A' WHERE (note_sets.id IN (WITH RECURSIVE parent_noteset as (SELECT id FROM note_sets where id = 8304085 UNION SELECT note_sets.id FROM parent_noteset parent_noteset, note_sets note_sets WHERE note_sets.parent_id = parent_noteset.id) SELECT id FROM parent_noteset))
CareCloud_Prod-# ;
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Hash Left Join (cost=4704563.58..5126773.60 rows=10184900 width=773) (actual time=14414.946..14554.962 rows=52 loops=1)
Hash Cond: (public.note_sets.note_set_source_id = note_set_sources.id)
-> Hash Right Join (cost=4704562.22..4986729.86 rows=10184900 width=720) (actual time=14414.908..14554.878 rows=52 loops=1)
Hash Cond: (notes.note_set_id = public.note_sets.id)
-> Seq Scan on notes (cost=0.00..33097.97 rows=883383 width=680) (actual time=0.021..292.329 rows=882307 loops=1)
Filter: (status = 'A'::bpchar)
Rows Removed by Filter: 862
-> Hash (cost=4497680.97..4497680.97 rows=10184900 width=40) (actual time=13848.559..13848.559 rows=46 loops=1)
Buckets: 524288 Batches: 4 Memory Usage: 7kB
-> Nested Loop (cost=4496147.89..4497680.97 rows=10184900 width=40) (actual time=13847.537..13848.125 rows=46 loops=1)
-> HashAggregate (cost=4496147.89..4496149.89 rows=200 width=4) (actual time=13847.410..13847.425 rows=46 loops=1)
-> CTE Scan on parent_noteset (cost=4495503.38..4495900.00 rows=19831 width=4) (actual time=0.058..13847.350 rows=46 loops=1)
CTE parent_noteset
-> Recursive Union (cost=0.00..4495503.38 rows=19831 width=4) (actual time=0.057..13847.284 rows=46 loops=1)
-> Index Only Scan using note_sets_pkey on note_sets (cost=0.00..7.85 rows=1 width=4) (actual time=0.054..0.055 rows=1 loops=1)
Index Cond: (id = 8304085)
Heap Fetches: 1
-> Hash Join (cost=0.33..449509.89 rows=1983 width=4) (actual time=2788.672..4615.686 rows=15 loops=3)
Hash Cond: (note_sets.parent_id = parent_noteset.id)
-> Seq Scan on note_sets (cost=0.00..373102.99 rows=20369799 width=8) (actual time=0.006..2288.076 rows=20355654 loops=3)
-> Hash (cost=0.20..0.20 rows=10 width=4) (actual time=0.006..0.006 rows=15 loops=3)
Buckets: 1024 Batches: 1 Memory Usage: 1kB
-> WorkTable Scan on parent_noteset (cost=0.00..0.20 rows=10 width=4) (actual time=0.001..0.003 rows=15 loops=3)
-> Index Scan using note_sets_pkey on note_sets (cost=0.00..7.65 rows=1 width=40) (actual time=0.014..0.014 rows=1 loops=46)
Index Cond: (id = parent_noteset.id)
-> Hash (cost=1.16..1.16 rows=16 width=53) (actual time=0.010..0.010 rows=16 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 2kB
-> Seq Scan on note_set_sources (cost=0.00..1.16 rows=16 width=53) (actual time=0.004..0.005 rows=16 loops=1)
Total runtime: 14555.254 ms
(29 rows)
CareCloud_Prod=#
# SELECT note_sets."id" AS t0_r0, note_sets."note_set_source_id" AS t0_r1, note_sets."parent_id" AS t0_r2, note_sets."business_entity_id" AS t0_r3, note_sets."created_at" AS t0_r4, note_sets."updated_at" AS t0_r5, note_sets."created_by" AS t0_r6, note_sets."updated_by" AS t0_r7, note_set_sources."id" AS t1_r0, note_set_sources."name" AS t1_r1, note_set_sources."code" AS t1_r2, note_set_sources."description" AS t1_r3, note_set_sources."status" AS t1_r4, note_set_sources."created_at" AS t1_r5, note_set_sources."updated_at" AS t1_r6, note_set_sources."created_by" AS t1_r7, note_set_sources."updated_by" AS t1_r8, notes."id" AS t2_r0, notes."note_set_id" AS t2_r1, notes."subject" AS t2_r2, notes."text" AS t2_r3, notes."status" AS t2_r4, notes."is_dissmissable" AS t2_r5, notes."is_home" AS t2_r6, notes."created_at" AS t2_r7, notes."updated_at" AS t2_r8, notes."created_by" AS t2_r9, notes."updated_by" AS t2_r10 FROM note_sets LEFT OUTER JOIN note_set_sources ON note_set_sources.id = note_sets.note_set_source_id LEFT OUTER JOIN notes ON notes.note_set_id = note_sets.id AND notes."status" = E'A' WHERE (note_sets.id IN (WITH RECURSIVE parent_noteset as (SELECT id FROM note_sets where id = 8304085 UNION SELECT note_sets.id FROM parent_noteset parent_noteset, note_sets note_sets WHERE note_sets.parent_id = parent_noteset.id) SELECT id FROM parent_noteset));
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Hash Left Join (cost=249847.72..670928.98 rows=10180954 width=1512) (actual time=692.423..829.258 rows=48 loops=1)
Hash Cond: (public.note_sets.note_set_source_id = note_set_sources.id)
-> Hash Right Join (cost=249846.36..530939.50 rows=10180954 width=718) (actual time=692.382..829.180 rows=48 loops=1)
Hash Cond: (notes.note_set_id = public.note_sets.id)
-> Seq Scan on notes (cost=0.00..32981.14 rows=878550 width=678) (actual time=0.027..413.972 rows=878529 loops=1)
Filter: (status = 'A'::bpchar)
-> Hash (cost=43045.44..43045.44 rows=10180954 width=40) (actual time=22.904..22.904 rows=46 loops=1)
Buckets: 524288 Batches: 4 Memory Usage: 2kB
-> Nested Loop (cost=41106.18..43045.44 rows=10180954 width=40) (actual time=12.319..22.738 rows=46 loops=1)
-> HashAggregate (cost=41106.18..41108.18 rows=200 width=4) (actual time=11.873..11.889 rows=46 loops=1)
-> CTE Scan on parent_noteset (cost=40459.39..40857.41 rows=19901 width=4) (actual time=0.492..11.843 rows=46 loops=1)
CTE parent_noteset
-> Recursive Union (cost=0.00..40459.39 rows=19901 width=4) (actual time=0.489..11.822 rows=46 loops=1)
-> Index Scan using note_sets_pkey on note_sets (cost=0.00..10.50 rows=1 width=4) (actual time=0.484..0.485 rows=1 loops=1)
Index Cond: (id = 8304085)
-> Nested Loop (cost=0.00..4005.09 rows=1990 width=4) (actual time=1.534..3.764 rows=15 loops=3)
-> WorkTable Scan on parent_noteset (cost=0.00..0.20 rows=10 width=4) (actual time=0.000..0.001 rows=15 loops=3)
-> Index Scan using note_sets_parent_id_idx on note_sets (cost=0.00..398.00 rows=199 width=8) (actual time=0.216..0.244 rows=1 loops=46)
Index Cond: (parent_id = parent_noteset.id)
-> Index Scan using note_sets_pkey on note_sets (cost=0.00..9.67 rows=1 width=40) (actual time=0.234..0.234 rows=1 loops=46)
Index Cond: (id = parent_noteset.id)
-> Hash (cost=1.16..1.16 rows=16 width=794) (actual time=0.020..0.020 rows=16 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 2kB
-> Seq Scan on note_set_sources (cost=0.00..1.16 rows=16 width=794) (actual time=0.012..0.014 rows=16 loops=1)
Total runtime: 829.657 ms
(25 rows)
Dave Cramer
dave.cramer(at)credativ(dot)ca
http://www.credativ.ca
Dave Cramer <pg@fastcrypt.com> writes: > This query is a couple orders of magnitude slower the first result is > 9.2.1, the second 9.1 Hm, the planner's evidently doing the wrong thing inside the recursive union, but not obvious why. Can you extract a self-contained test case? regards, tom lane
Tom,
Dave Cramer
dave.cramer(at)credativ(dot)ca
http://www.credativ.ca
Will try to get one ASAP.
Dave
Dave Cramer
dave.cramer(at)credativ(dot)ca
http://www.credativ.ca
On Mon, Nov 12, 2012 at 3:43 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
Dave Cramer <pg@fastcrypt.com> writes:Hm, the planner's evidently doing the wrong thing inside the recursive
> This query is a couple orders of magnitude slower the first result is
> 9.2.1, the second 9.1
union, but not obvious why. Can you extract a self-contained test case?
regards, tom lane
Hello Tom,
Could you elaborate on this? I'm trying to learn the explain plans of postgresql and i would like to know if we're looking at the same clue's.
To me, i see a mismatch between the optimizer and the actual records retrieved in the fast SQL as well, so plan instability is a realistic scenario. For the slow query, I thought to see a problem in the part below the ' recursive union' :
the HASH join is more expensive that the nested loop. ( hints are not yet implemented in Postgresql , aren't they? )
So the SQL text is:
explain analyze
SELECT
note_sets."id" AS t0_r0,
...
notes."updated_by" AS t2_r10
FROM
note_sets
LEFT OUTER JOIN note_set_sources ON note_set_sources.id = note_sets.note_set_source_id
LEFT OUTER JOIN notes ON notes.note_set_id = note_sets.id AND
notes."status" = E'A'
WHERE
(note_sets.id IN (WITH RECURSIVE parent_noteset as
(SELECT id FROM note_sets where id = 8304085
UNION
SELECT note_sets.id FROM
parent_noteset parent_noteset,
note_sets note_sets
WHERE note_sets.parent_id = parent_noteset.id) SELECT id FROM parent_noteset))
IMHO, the plan goes wrong at the part
SELECT note_sets.id FROM
parent_noteset parent_noteset,
note_sets note_sets
WHERE note_sets.parent_id = parent_noteset.id)
Do you agree?
Could you elaborate on this? I'm trying to learn the explain plans of postgresql and i would like to know if we're looking at the same clue's.
To me, i see a mismatch between the optimizer and the actual records retrieved in the fast SQL as well, so plan instability is a realistic scenario. For the slow query, I thought to see a problem in the part below the ' recursive union' :
the HASH join is more expensive that the nested loop. ( hints are not yet implemented in Postgresql , aren't they? )
So the SQL text is:
explain analyze
SELECT
note_sets."id" AS t0_r0,
...
notes."updated_by" AS t2_r10
FROM
note_sets
LEFT OUTER JOIN note_set_sources ON note_set_sources.id = note_sets.note_set_source_id
LEFT OUTER JOIN notes ON notes.note_set_id = note_sets.id AND
notes."status" = E'A'
WHERE
(note_sets.id IN (WITH RECURSIVE parent_noteset as
(SELECT id FROM note_sets where id = 8304085
UNION
SELECT note_sets.id FROM
parent_noteset parent_noteset,
note_sets note_sets
WHERE note_sets.parent_id = parent_noteset.id) SELECT id FROM parent_noteset))
IMHO, the plan goes wrong at the part
SELECT note_sets.id FROM
parent_noteset parent_noteset,
note_sets note_sets
WHERE note_sets.parent_id = parent_noteset.id)
Do you agree?
> From: tgl@sss.pgh.pa.us
> To: pg@fastcrypt.com
> CC: pgsql-performance@postgresql.org
> Subject: Re: [PERFORM] performance regression with 9.2
> Date: Mon, 12 Nov 2012 15:43:53 -0500
>
> Dave Cramer <pg@fastcrypt.com> writes:
> > This query is a couple orders of magnitude slower the first result is
> > 9.2.1, the second 9.1
>
> Hm, the planner's evidently doing the wrong thing inside the recursive
> union, but not obvious why. Can you extract a self-contained test case?
>
> regards, tom lane
>
>
> --
> Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-performance
> To: pg@fastcrypt.com
> CC: pgsql-performance@postgresql.org
> Subject: Re: [PERFORM] performance regression with 9.2
> Date: Mon, 12 Nov 2012 15:43:53 -0500
>
> Dave Cramer <pg@fastcrypt.com> writes:
> > This query is a couple orders of magnitude slower the first result is
> > 9.2.1, the second 9.1
>
> Hm, the planner's evidently doing the wrong thing inside the recursive
> union, but not obvious why. Can you extract a self-contained test case?
>
> regards, tom lane
>
>
> --
> Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-performance
Willem Leenen <willem_leenen@hotmail.com> writes: > To me, i see a mismatch between the optimizer and the actual records > retrieved in the fast SQL as well, so plan instability is a realistic > scenario. Well, the rowcount estimates for a recursive union are certainly pretty bogus, but those are the same either way. The reason this looks like a bug and not just statistical issues is that the join inside the recursive union is done as a hash, even though that's much more expensive (according to the estimates, not reality) than a nestloop. Presumably the planner is failing to even consider a nestloop-with-inner-indexscan join there, else it would have picked that type of plan. Why it's failing is as yet unclear. regards, tom lane
Dave Cramer <pg@fastcrypt.com> writes: > This query is a couple orders of magnitude slower the first result is > 9.2.1, the second 9.1 Thanks for sending me the test case off-list. I found the reason why I'd not been able to reproduce the problem: the index you're hoping it will use is declared "note_sets_parent_id_idx" btree (parent_id) WHERE parent_id IS NOT NULL Apparently 9.2 is less bright than 9.1 about when it can use a partial index. I'm not sure where I broke that, but will look. regards, tom lane