pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedperformance regression with 9.2
6+ messages / 3 participants
[nested] [flat]
* performance regression with 9.2
@ 2012-11-12 19:49 Dave Cramer <pg@fastcrypt.com>
0 siblings, 2 replies; 6+ messages in thread
From: Dave Cramer @ 2012-11-12 19:49 UTC (permalink / raw)
To: pgsql-performance
This query is a couple orders of magnitude slower the first result is
9.2.1, the second 9.1
=# 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
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: performance regression with 9.2
@ 2012-11-12 20:43 Tom Lane <tgl@sss.pgh.pa.us>
parent: Dave Cramer <pg@fastcrypt.com>
1 sibling, 2 replies; 6+ messages in thread
From: Tom Lane @ 2012-11-12 20:43 UTC (permalink / raw)
To: Dave Cramer <pg@fastcrypt.com>; +Cc: pgsql-performance
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
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: performance regression with 9.2
@ 2012-11-12 20:53 Dave Cramer <pg@fastcrypt.com>
parent: Tom Lane <tgl@sss.pgh.pa.us>
1 sibling, 0 replies; 6+ messages in thread
From: Dave Cramer @ 2012-11-12 20:53 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: pgsql-performance
Tom,
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:
> > 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
>
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: performance regression with 9.2
@ 2012-11-12 21:13 Willem Leenen <willem_leenen@hotmail.com>
parent: Tom Lane <tgl@sss.pgh.pa.us>
1 sibling, 1 reply; 6+ messages in thread
From: Willem Leenen @ 2012-11-12 21:13 UTC (permalink / raw)
To: tgl@sss.pgh.pa.us; pg@fastcrypt.com; +Cc: pgsql-performance
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?
> 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
=
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: performance regression with 9.2
@ 2012-11-12 21:26 Tom Lane <tgl@sss.pgh.pa.us>
parent: Willem Leenen <willem_leenen@hotmail.com>
0 siblings, 0 replies; 6+ messages in thread
From: Tom Lane @ 2012-11-12 21:26 UTC (permalink / raw)
To: Willem Leenen <willem_leenen@hotmail.com>; +Cc: pg@fastcrypt.com; 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
^ permalink raw reply [nested|flat] 6+ messages in thread
* Re: performance regression with 9.2
@ 2012-11-15 19:21 Tom Lane <tgl@sss.pgh.pa.us>
parent: Dave Cramer <pg@fastcrypt.com>
1 sibling, 0 replies; 6+ messages in thread
From: Tom Lane @ 2012-11-15 19:21 UTC (permalink / raw)
To: Dave Cramer <pg@fastcrypt.com>; +Cc: pgsql-performance
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
^ permalink raw reply [nested|flat] 6+ messages in thread
end of thread, other threads:[~2012-11-15 19:21 UTC | newest]
Thread overview: 6+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2012-11-12 19:49 performance regression with 9.2 Dave Cramer <pg@fastcrypt.com>
2012-11-12 20:43 ` Tom Lane <tgl@sss.pgh.pa.us>
2012-11-12 20:53 ` Dave Cramer <pg@fastcrypt.com>
2012-11-12 21:13 ` Willem Leenen <willem_leenen@hotmail.com>
2012-11-12 21:26 ` Tom Lane <tgl@sss.pgh.pa.us>
2012-11-15 19:21 ` Tom Lane <tgl@sss.pgh.pa.us>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox