On 29 January 2011 09:11, Uwe Schroeder <u...@oss4u.com> wrote: > > 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 shorter message. 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.145 rows=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=1641 loops=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=1641 loops=1) > Hash Cond: (c.from_id = b.id) > -> Index Scan using > bprofile_comments_status_idx on bprofile_comments c (cost=0.00..2558.77 > rows=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=14782 loops=1) > -> Hash Left Join > (cost=61.50..1726.15 rows=7632 width=8) (actual time=2.622..119.268 > rows=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) (actual time=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=231 loops=1) > -> Nested Loop > (cost=0.00..55.12 rows=510 width=13) (actual time=0.136..1.909 rows=231 > loops=1) > -> Seq Scan on > tg_group gi (cost=0.00..1.07 rows=1 width=13) (actual time=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.80 rows=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=1025 width=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.015 rows=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.011 rows=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=15292 loops=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.541 > rows=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=261 loops=1) > -> Seq Scan on tg_group gi > (cost=0.00..1.18 rows=1 width=13) (actual time=0.032..0.039 rows=1 loops=1) > Filter: ((group_name)::text > = 'Club16'::text) > -> Index Scan using > user_group_group_idx on user_group ugi (cost=0.00..65.39 rows=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=1751 width=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.017 rows=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.011 rows=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 suddenly shows 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 iowait and 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
The estimated rows on your 9.0 instance look wildly inaccurate, suggesting the stats haven't been collected. Have you run a VACUUM ANALYZE on the whole database? -- Thom Brown Twitter: @darkixion IRC (freenode): dark_ixion Registered Linux user: #516935 -- Sent via pgsql-general mailing list (pgsql-general@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-general