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
--
Sent via pgsql-general mailing list (pgsql-general@xxxxxxxxxxxxxx)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general
