Why is 8.4 and 9.0 so much slower on some queries?

Hello everyone,

this is very odd, particularly because there's obviously nobody having these issues when I google for it.

I have a 8.3 database and decided for various reasons to upgrade to 8.4. I also tried 9.0 - same results.

On the exactly same hardware with the exactly same configuration, some queries perform a factor of 100000 slower on 8.4 and 9.0 than on 8.3
A factor that large leads me to believe that I'm missing something or the queries in question were flawed to begin with (which may very well be)

Here's an example:
I have a forum with a table for the threads and a table for the posts. There's also a table which keeps user specific things (email, user_id) and a table that lets me assign roles (not database roles) to
a user (i.e. is an admin, is a normal user etc).

The posts table references the threads table (obviously, a post belongs to a certain thread). I can post table specs, but I think it's rather obvious, so I'll go to the explain outputs.

There is a view which contains the base query:

create or replace view v_grouptopics_helper_club16 as
select t.id, t.group_id, p.id as postid from groups_threads t left outer join groups_posts p on p.thread_id=t.id AND t.deleted=false AND p.id = (SELECT p.id FROM groups_posts p LEFT OUTER JOIN
user_group ugi on ugi.user_id=p.posted_by_uid AND ugi.group_id=16 WHERE ugi.group_id IS NULL AND p.thread_id=t.id ORDER BY date_posted desc limit 1) LEFT OUTER JOIN user_group ugt on
ugt.user_id=(select uid from bprofile where id=t.posted_by) AND ugt.group_id=16 WHERE ugt.group_id IS NULL AND t.deleted=false ORDER BY p.date_posted DESC;

So basically what I want is a list of latest forum topics with the latest post where the user who posted either is not in the role with number 16.

When I do a
explain analyze select * from v_grouptopics_helper_club16 where group_id=199;

on the 8.3 server I get this result:

Subquery Scan v_grouptopics_helper_club16 (cost=4117.52..4118.17 rows=52 width=12) (actual time=5.959..6.173 rows=104 loops=1)
-> Sort (cost=4117.52..4117.65 rows=52 width=20) (actual time=5.957..6.029 rows=104 loops=1)
Sort Key: p.date_posted
Sort Method: quicksort Memory: 21kB
-> Nested Loop Left Join (cost=84.63..4116.04 rows=52 width=20) (actual time=0.842..5.775 rows=104 loops=1)
Join Filter: ((NOT t.deleted) AND (p.thread_id = t.id))
-> Hash Left Join (cost=71.37..2445.93 rows=52 width=9) (actual time=0.791..2.017 rows=104 loops=1)
Hash Cond: ((subplan) = ugt.user_id)
Filter: (ugt.group_id IS NULL)
-> Index Scan using groups_threads_group_idx on groups_threads t (cost=0.00..237.18 rows=104 width=13) (actual time=0.021..0.257 rows=104 loops=1)
Index Cond: (group_id = 199)
Filter: (NOT deleted)
-> Hash (cost=67.41..67.41 rows=317 width=8) (actual time=0.741..0.741 rows=318 loops=1)
-> Index Scan using user_group_club16_idx on user_group ugt (cost=0.00..67.41 rows=317 width=8) (actual time=0.024..0.430 rows=318 loops=1)
Index Cond: (group_id = 16)
SubPlan
-> Index Scan using bprofile_pkey on bprofile (cost=0.00..5.87 rows=1 width=4) (actual time=0.005..0.006 rows=1 loops=104)
Index Cond: (id = $2)
-> Index Scan using groups_posts_pk on groups_posts p (cost=13.26..18.84 rows=1 width=16) (actual time=0.005..0.006 rows=1 loops=104)
Index Cond: (p.id = (subplan))
SubPlan
-> Limit (cost=0.00..13.26 rows=1 width=12) (actual time=0.024..0.024 rows=1 loops=104)
-> Nested Loop Left Join (cost=0.00..238.68 rows=18 width=12) (actual time=0.022..0.022 rows=1 loops=104)
Filter: (ugi.group_id IS NULL)
-> Index Scan Backward using groups_posts_thread_date_idx on groups_posts p (cost=0.00..85.96 rows=35 width=16) (actual time=0.012..0.012 rows=1 loops=104)
Index Cond: (thread_id = $0)
-> Index Scan using user_group_uid_idx on user_group ugi (cost=0.00..4.35 rows=1 width=8) (actual time=0.007..0.007 rows=0 loops=104)
Index Cond: (ugi.user_id = p.posted_by_uid)
Filter: (ugi.group_id = 16)
-> Limit (cost=0.00..13.26 rows=1 width=12) (actual time=0.024..0.024 rows=1 loops=104)
-> Nested Loop Left Join (cost=0.00..238.68 rows=18 width=12) (actual time=0.022..0.022 rows=1 loops=104)
Filter: (ugi.group_id IS NULL)
-> Index Scan Backward using groups_posts_thread_date_idx on groups_posts p (cost=0.00..85.96 rows=35 width=16) (actual time=0.012..0.012 rows=1 loops=104)
Index Cond: (thread_id = $0)
-> Index Scan using user_group_uid_idx on user_group ugi (cost=0.00..4.35 rows=1 width=8) (actual time=0.007..0.007 rows=0 loops=104)
Index Cond: (ugi.user_id = p.posted_by_uid)
Filter: (ugi.group_id = 16)
Total runtime: 6.365 ms
(38 rows)

So the query executes in around 6ms, which is just dandy.

Here is the same output for the 8.4 server - keep in mind it's identical machines with identical configuration (except the 8.4 machine has more memory, but the config is the same):
Subquery Scan v_grouptopics_helper_club16 (cost=7054.97..7054.99 rows=1 width=12) (actual time=1354900.705..1354900.838 rows=105 loops=1)
-> Sort (cost=7054.97..7054.98 rows=1 width=20) (actual time=1354900.702..1354900.747 rows=105 loops=1)
Sort Key: p.date_posted
Sort Method: quicksort Memory: 21kB
-> Nested Loop Left Join (cost=62.53..7054.96 rows=1 width=20) (actual time=1.594..1354900.490 rows=105 loops=1)
Join Filter: ((NOT t.deleted) AND (p.id = (SubPlan 1)))
-> Hash Anti Join (cost=62.53..2432.89 rows=1 width=9) (actual time=0.639..2.976 rows=105 loops=1)
Hash Cond: ((SubPlan 2) = ugt.user_id)
-> Index Scan using groups_threads_group_idx on groups_threads t (cost=0.00..233.02 rows=104 width=13) (actual time=0.024..0.528 rows=105 loops=1)
Index Cond: (group_id = 199)
Filter: (NOT deleted)
-> Hash (cost=58.55..58.55 rows=318 width=4) (actual time=0.592..0.592 rows=318 loops=1)
-> Index Scan using user_group_club16_idx on user_group ugt (cost=0.00..58.55 rows=318 width=4) (actual time=0.031..0.380 rows=318 loops=1)
Index Cond: (group_id = 16)
SubPlan 2
-> Index Scan using bprofile_pkey on bprofile (cost=0.00..5.87 rows=1 width=4) (actual time=0.011..0.012 rows=1 loops=105)
Index Cond: (id = $1)
-> Index Scan using groups_posts_threadid_idx on groups_posts p (cost=0.00..58.24 rows=34 width=16) (actual time=0.033..2.223 rows=919 loops=105)
Index Cond: (p.thread_id = t.id)
SubPlan 1
-> Limit (cost=134.21..134.22 rows=1 width=12) (actual time=14.034..14.034 rows=1 loops=96470)
-> Sort (cost=134.21..134.22 rows=1 width=12) (actual time=14.030..14.030 rows=1 loops=96470)
Sort Key: p.date_posted
Sort Method: top-N heapsort Memory: 17kB
-> Hash Anti Join (cost=62.53..134.20 rows=1 width=12) (actual time=0.038..10.850 rows=4540 loops=96470)
Hash Cond: (p.posted_by_uid = ugi.user_id)
-> Index Scan using groups_posts_threadid_idx on groups_posts p (cost=0.00..71.29 rows=34 width=16) (actual time=0.034..5.287 rows=4540 loops=96470)
Index Cond: (thread_id = $0)
-> Hash (cost=58.55..58.55 rows=318 width=4) (actual time=0.511..0.511 rows=318 loops=1)
-> Index Scan using user_group_club16_idx on user_group ugi (cost=0.00..58.55 rows=318 width=4) (actual time=0.024..0.301 rows=318 loops=1)
Index Cond: (group_id = 16)
Total runtime: 1354901.025 ms

Not only does the plan look majorly different, it also loops a gazillion times and seems to get it all wrong.

... and no, the database was dumped and restored, vacuumed, reindexed and analyzed. It's just that something in the planner is different.

BTW: a query eliminating the left outer joins in favor of "not in" or "not exists" subqueries leads to much better results, but is still in the 500ms area, thus nowhere near the 6ms I used to have.

Does anyone have any smart ideas about this? It grinds my website to a halt.

Thanks

Uwe

Uwe Schroeder <uwe(at)oss4u(dot)com> writes:
> I have a 8.3 database and decided for various reasons to upgrade to 8.4. I also tried 9.0 - same results.
> On the exactly same hardware with the exactly same configuration, some queries perform a factor of 100000 slower on 8.4 and 9.0 than on 8.3

Hmm ... the problem here seems to come from the much poorer size
estimate from the t/ugt antijoin:

> -> Hash Left Join (cost=71.37..2445.93 rows=52 width=9) (actual time=0.791..2.017 rows=104 loops=1)
> Hash Cond: ((subplan) = ugt.user_id)
> Filter: (ugt.group_id IS NULL)

> -> Hash Anti Join (cost=62.53..2432.89 rows=1 width=9) (actual time=0.639..2.976 rows=105 loops=1)
> Hash Cond: ((SubPlan 2) = ugt.user_id)

Now, 8.3 has no idea what it's doing here, and it's just luck that it
produces an estimate that's only a factor of 2 off from reality. 8.4
actually understands that it's dealing with an antijoin, and with that
greater knowledge it produces ... a much worse estimate :-(. And that
sends it into the weeds about how to perform the higher-level join.

While I don't have your specific example to try, I did some
experimenting with queries of this form, and I noticed that 8.4's
heuristic in eqjoinsel_semi() was going completely nuts and estimating
that all rows in the lefthand side have join partners (thus, no rows out
of the antijoin). This is because it has stats for one side of the
comparison operator but not the other side (the one with the
sub-select). But it's taking the totally-made-up ndistinct estimate for
the sub-select at face value. It needs to be a bit warier I think.

In general you might want to think about whether you can recast this
query to avoid the sub-selects in the join conditions. The planner
isn't terribly bright about sub-selects in the first place, and you're
putting them in places where quality estimates are really critical to
getting a good plan.

regards, tom lane

> Uwe Schroeder <uwe(at)oss4u(dot)com> writes:
> > I have a 8.3 database and decided for various reasons to upgrade to 8.4.
> > I also tried 9.0 - same results. On the exactly same hardware with the
> > exactly same configuration, some queries perform a factor of 100000
> > slower on 8.4 and 9.0 than on 8.3
>
> Hmm ... the problem here seems to come from the much poorer size
>
> estimate from the t/ugt antijoin:
> > -> Hash Left Join (cost=71.37..2445.93 rows=52 width=9)
> > (actual time=0.791..2.017 rows=104 loops=1)
> >
> > Hash Cond: ((subplan) = ugt.user_id)
> > Filter: (ugt.group_id IS NULL)
> >
> > -> Hash Anti Join (cost=62.53..2432.89 rows=1 width=9)
> > (actual time=0.639..2.976 rows=105 loops=1)
> >
> > Hash Cond: ((SubPlan 2) = ugt.user_id)
>
> Now, 8.3 has no idea what it's doing here, and it's just luck that it
> produces an estimate that's only a factor of 2 off from reality. 8.4
> actually understands that it's dealing with an antijoin, and with that
> greater knowledge it produces ... a much worse estimate :-(. And that
> sends it into the weeds about how to perform the higher-level join.
>
> While I don't have your specific example to try, I did some
> experimenting with queries of this form, and I noticed that 8.4's
> heuristic in eqjoinsel_semi() was going completely nuts and estimating
> that all rows in the lefthand side have join partners (thus, no rows out
> of the antijoin). This is because it has stats for one side of the
> comparison operator but not the other side (the one with the
> sub-select). But it's taking the totally-made-up ndistinct estimate for
> the sub-select at face value. It needs to be a bit warier I think.
>
> In general you might want to think about whether you can recast this
> query to avoid the sub-selects in the join conditions. The planner
> isn't terribly bright about sub-selects in the first place, and you're
> putting them in places where quality estimates are really critical to
> getting a good plan.

Ahhh, that actually makes sense. Since this example isn't the only spot where
I have this kind of query (I tweaked those for weeks to run fast, but always
on a 8.3 server), I'll just downgrade to a 8.3 for production.

If you're interested, I can provide database and data for you to toy with as
there's nothing particularly secretive in that data except email addresses
which can be erased as they're not needed for anything.

By the end of the day I'll set up another machine with a 9.0 and start
changing the queries - simply because 9.0 is a heck of a lot faster with most
things - except these kind of left outer joins and subselects.

Thanks for your response.

Uwe

On Tue, Apr 12, 2011 at 12:58 AM, Uwe Schroeder <uwe(at)oss4u(dot)com> wrote:
>
>
>> Uwe Schroeder <uwe(at)oss4u(dot)com> writes:
>> > I have a 8.3 database and decided for various reasons to upgrade to 8.4.
>> > I also tried 9.0 - same results. On the exactly same hardware with the
>> > exactly same configuration, some queries perform a factor of 100000
>> > slower on 8.4 and 9.0 than on 8.3
>>
>> Hmm ... the problem here seems to come from the much poorer size
>>
>> estimate from the t/ugt antijoin:
>> >                ->  Hash Left Join  (cost=71.37..2445.93 rows=52 width=9)
>> >                (actual time=0.791..2.017 rows=104 loops=1)
>> >
>> >                      Hash Cond: ((subplan) = ugt.user_id)
>> >                      Filter: (ugt.group_id IS NULL)
>> >
>> >                ->  Hash Anti Join  (cost=62.53..2432.89 rows=1 width=9)
>> >                (actual time=0.639..2.976 rows=105 loops=1)
>> >
>> >                      Hash Cond: ((SubPlan 2) = ugt.user_id)
>>
>> Now, 8.3 has no idea what it's doing here, and it's just luck that it
>> produces an estimate that's only a factor of 2 off from reality.  8.4
>> actually understands that it's dealing with an antijoin, and with that
>> greater knowledge it produces ... a much worse estimate :-(.  And that
>> sends it into the weeds about how to perform the higher-level join.
>>
>> While I don't have your specific example to try, I did some
>> experimenting with queries of this form, and I noticed that 8.4's
>> heuristic in eqjoinsel_semi() was going completely nuts and estimating
>> that all rows in the lefthand side have join partners (thus, no rows out
>> of the antijoin).  This is because it has stats for one side of the
>> comparison operator but not the other side (the one with the
>> sub-select).  But it's taking the totally-made-up ndistinct estimate for
>> the sub-select at face value.  It needs to be a bit warier I think.
>>
>> In general you might want to think about whether you can recast this
>> query to avoid the sub-selects in the join conditions.  The planner
>> isn't terribly bright about sub-selects in the first place, and you're
>> putting them in places where quality estimates are really critical to
>> getting a good plan.
>
>
> Ahhh, that actually makes sense. Since this example isn't the only spot where
> I have this kind of query (I tweaked those for weeks to run fast, but always
> on a 8.3 server), I'll just downgrade to a 8.3 for production.
>
> If you're interested, I can provide database and data for you to toy with as
> there's nothing particularly secretive in that data except email addresses
> which can be erased as they're not needed for anything.

Tom already checked in a fix -- if you are able to build from source
you should be able to test it yourself. 9.0.4 and 8.4.8 will contain
the fix. In the short term, you can get it from git (follow
instructions here): http://wiki.postgresql.org/wiki/Working_with_Git.
Build/install instructions here:
http://www.postgresql.org/docs/9.0/interactive/installation.html.

you will want the branch REL8_4_STABLE or REL9_0_STABLE.

merlin