PG9.0 planner difference to 8.3 -> majorly bad performance - Mailing list pgsql-general

Maybe someone here can make sense of this.
I'm trying to upgrade a 8.3 system to a 9.0 system. Usual procedure dump, restore, vac full, reindex.

Both - old and new - run on the same hardware and the postgresql.conf settings are identical.

You'll probably ask for the table definitions, which I'm happy to provide, but I'll omit them here for the sake of a
shortermessage. Basically everything is identical, data, tables, indexes, harware,  
config.

I should mention that the "tables" are really views - maybe something in the views changed in 9.0.2

I run this query on the 8.3 system:

explain analyze SELECT count(v_bprofile_comments_club16.id)  FROM v_bprofile_comments_club16

              
WHERE v_bprofile_comments_club16.profile_id = '5584' AND v_bprofile_comments_club16.approved = true;
                                                                                              QUERY PLAN
                                                                              

------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=6294.37..6294.38 rows=1 width=4) (actual time=269.633..269.635 rows=1 loops=1)
   ->  Nested Loop  (cost=1889.71..6273.06 rows=8523 width=4) (actual time=156.585..266.325 rows=1641 loops=1)
         ->  Nested Loop  (cost=1889.71..5858.47 rows=779 width=16) (actual time=156.565..237.216 rows=1641 loops=1)
               ->  Nested Loop  (cost=1889.71..4488.01 rows=763 width=12) (actual time=156.453..200.174 rows=1641
loops=1)
                     ->  Index Scan using bprofile_pkey on bprofile m  (cost=0.00..4.27 rows=1 width=4) (actual
time=0.140..0.145rows=1 loops=1) 
                           Index Cond: (id = 5584)
                     ->  Hash Left Join  (cost=1889.71..4476.11 rows=763 width=16) (actual time=156.302..194.762
rows=1641loops=1) 
                           Hash Cond: (b.uid = ug.user_id)
                           ->  Hash Join  (cost=1821.55..4399.44 rows=763 width=20) (actual time=151.372..183.103
rows=1641loops=1) 
                                 Hash Cond: (c.from_id = b.id)
                                 ->  Index Scan using bprofile_comments_status_idx on bprofile_comments c
(cost=0.00..2558.77rows=1531 width=12) (actual time=0.140..21.559 rows=1660 loops=1) 
                                       Index Cond: ((profile_id = 5584) AND (approved = true))
                                       Filter: approved
                                 ->  Hash  (cost=1726.15..1726.15 rows=7632 width=8) (actual time=151.131..151.131
rows=14782loops=1) 
                                       ->  Hash Left Join  (cost=61.50..1726.15 rows=7632 width=8) (actual
time=2.622..119.268rows=14782 loops=1) 
                                             Hash Cond: (b.uid = ugi.user_id)
                                             Filter: (gi.group_name IS NULL)
                                             ->  Seq Scan on bprofile b  (cost=0.00..1579.44 rows=15265 width=8)
(actualtime=0.058..64.033 rows=15265 loops=1) 
                                                   Filter: (NOT deleted)
                                             ->  Hash  (cost=55.12..55.12 rows=510 width=13) (actual time=2.526..2.526
rows=231loops=1) 
                                                   ->  Nested Loop  (cost=0.00..55.12 rows=510 width=13) (actual
time=0.136..1.909rows=231 loops=1) 
                                                         ->  Seq Scan on tg_group gi  (cost=0.00..1.07 rows=1 width=13)
(actualtime=0.041..0.050 rows=1 loops=1) 
                                                               Filter: ((group_name)::text = 'Club16'::text)
                                                         ->  Index Scan using user_group_group_idx on user_group ugi
(cost=0.00..45.80rows=660 width=8) (actual time=0.084..1.071 rows=231 loops=1) 
                                                               Index Cond: (ugi.group_id = gi.group_id)
                           ->  Hash  (cost=55.35..55.35 rows=1025 width=4) (actual time=4.866..4.866 rows=1025 loops=1)
                                 ->  Index Scan using user_group_group_idx on user_group ug  (cost=0.00..55.35
rows=1025width=4) (actual time=0.058..2.766 rows=1025 loops=1) 
                                       Index Cond: (group_id = 2)
               ->  Index Scan using bphotos_profile_primary_idx on bphotos p  (cost=0.00..1.78 rows=1 width=4) (actual
time=0.012..0.015rows=1 loops=1641)                                                 
                     Index Cond: ((p.profile_id = b.id) AND (p.is_primary = true))
                                                                                   
         ->  Index Scan using bphotos_profile_primary_idx on bphotos p  (cost=0.00..0.52 rows=1 width=4) (actual
time=0.008..0.011rows=1 loops=1641) 
               Index Cond: ((p.profile_id = b.id) AND (p.is_primary = true))
 Total runtime: 270.808 ms
(33 rows)


As you can see, the query performs nicely (for the hardware used).

Now I turn off the 8.3 instance and start the 9.0 instance. Remember, everything is identical. Here the same query
again:

explain analyze SELECT count(v_bprofile_comments_club16.id)  FROM v_bprofile_comments_club16

              
WHERE v_bprofile_comments_club16.profile_id = '5584' AND v_bprofile_comments_club16.approved = true;
                                                                                                     
                                                                                        QUERY PLAN
                                                                  

------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
                
 Aggregate  (cost=6278.48..6278.49 rows=1 width=4) (actual time=173253.190..173253.192 rows=1 loops=1)
   ->  Nested Loop  (cost=83.87..6278.45 rows=11 width=4) (actual time=5485.258..173248.693 rows=1851 loops=1)
         ->  Nested Loop  (cost=83.87..6275.95 rows=1 width=16) (actual time=5485.216..173213.895 rows=1851 loops=1)
               ->  Nested Loop  (cost=83.87..6269.67 rows=1 width=20) (actual time=5476.690..173168.446 rows=1851
loops=1)
                     Join Filter: (p.profile_id = c.from_id)
                     ->  Nested Loop  (cost=83.87..1919.14 rows=1 width=8) (actual time=2.940..971.939 rows=15288
loops=1)
                           ->  Hash Left Join  (cost=83.87..1918.44 rows=1 width=4) (actual time=2.784..297.862
rows=15292loops=1) 
                                 Hash Cond: (b.uid = ugi.user_id)
                                 Filter: (gi.group_name IS NULL)
                                 ->  Seq Scan on bprofile b  (cost=0.00..1703.49 rows=15846 width=8) (actual
time=0.044..166.541rows=15845 loops=1) 
                                       Filter: (NOT deleted)
                                 ->  Hash  (cost=75.22..75.22 rows=692 width=13) (actual time=2.667..2.667 rows=261
loops=1)
                                       Buckets: 1024  Batches: 1  Memory Usage: 8kB
                                       ->  Nested Loop  (cost=0.00..75.22 rows=692 width=13) (actual time=0.115..2.102
rows=261loops=1) 
                                             ->  Seq Scan on tg_group gi  (cost=0.00..1.18 rows=1 width=13) (actual
time=0.032..0.039rows=1 loops=1) 
                                                   Filter: ((group_name)::text = 'Club16'::text)
                                             ->  Index Scan using user_group_group_idx on user_group ugi
(cost=0.00..65.39rows=692 width=8) (actual time=0.071..1.229 rows=261 loops=1) 
                                                   Index Cond: (ugi.group_id = gi.group_id)
                           ->  Index Scan using bphotos_profile_primary_idx on bphotos p  (cost=0.00..0.69 rows=1
width=4)(actual time=0.027..0.032 rows=1 loops=15292) 
                                 Index Cond: ((p.profile_id = b.id) AND (p.is_primary = true))
                     ->  Index Scan using bprofile_comments_status_idx on bprofile_comments c  (cost=0.00..4328.64
rows=1751width=12) (actual time=0.033..8.097 rows=1872 loops=15288) 
                           Index Cond: ((c.profile_id = 5584) AND (c.approved = true))
                           Filter: c.approved
               ->  Index Scan using bprofile_pkey on bprofile m  (cost=0.00..6.27 rows=1 width=4) (actual
time=0.015..0.017rows=1 loops=1851) 
                     Index Cond: (m.id = 5584)
         ->  Index Scan using bphotos_profile_primary_idx on bphotos p  (cost=0.00..2.48 rows=1 width=4) (actual
time=0.009..0.011rows=1 loops=1851) 
               Index Cond: ((p.profile_id = p.profile_id) AND (p.is_primary = true))
 Total runtime: 173254.092 ms
(28 rows)


The duration suddenly goes from 270 milliseconds to 173 seconds! The index scan on bprofile_comments_status_idx
suddenlyshows 15288 loops, where it should be 1 loop just like before. So  
shomehow the 9.0 planner gets it all wrong.

I also noticed that normally I get an iowait with a few percent during such operations (on 8.3), where with pg9 I get 0
iowaitand 100% CPU. PG9 has a much smaller memory footprint than 8.3 in  
the same configuration - so this all makes very little sense to me. Maybe someone here has an idea.

Thanks

Uwe