Thread: PG9.0 planner difference to 8.3 -> majorly bad performance
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
* Uwe Schroeder (uwe@oss4u.com) wrote:
> Now I turn off the 8.3 instance and start the 9.0 instance. Remember, everything is identical. Here the same query
again:
Everything isn't identical if you just started PG 9.0 though- presumably
the 8.3 instance had everything cache'd already. What happens if you
run this query again under 9.0..?
> 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.
You do have a different plan, but both of them have a Nested Loop, with
a Hash table built inside it. The 9.0 does also do the index scan
inside the loop, but if you look at the actual time, that's not really
causing a huge difference. One thing I'm wondering about is if 9.0 is
getting a more accurate view of the amount of data and is realizing that
it might go over work_mem with the big Hash Left Join, and so decides
against it. What does your work_mem setting look like on each system?
Have you tried increasing it?
Thanks,
Stephen
> I also noticed that normally I get an iowait with a few percent during such operations (on 8.3), where with pg9 I get
0iowait 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@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-general
Attachment
On 29 January 2011 09:11, Uwe Schroeder <uwe@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 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)(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.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 0iowait 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
> On 29 January 2011 09:11, Uwe Schroeder <uwe@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? Yes, the database is vacuumed and analyzed. The bad plan from 9.0 improves by 2 seconds when I go for a really high statistics target of 5000.
> * Uwe Schroeder (uwe@oss4u.com) wrote: > > Now I turn off the 8.3 instance and start the 9.0 instance. Remember, everything is identical. Here the same query again: > Everything isn't identical if you just started PG 9.0 though- presumably > the 8.3 instance had everything cache'd already. What happens if you > run this query again under 9.0..? The 8.3 instance is also just started. I run both on the same system (for testing) so I turn one off to have the memory available. But yes, I did run the queries multiple times in a row with no major improvement. > > > 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. > > You do have a different plan, but both of them have a Nested Loop, with > a Hash table built inside it. The 9.0 does also do the index scan > inside the loop, but if you look at the actual time, that's not really > causing a huge difference. One thing I'm wondering about is if 9.0 is > getting a more accurate view of the amount of data and is realizing that > it might go over work_mem with the big Hash Left Join, and so decides > against it. What does your work_mem setting look like on each system? > Have you tried increasing it? What has me bummed is the index scan on 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) vs 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) Unless I read this wrong, the upper (8.3) index scan fetches 1660 rows in up to 21ms the 9.0 plan comes up with an index scan on the same data which fetches 1872 rows in 8 ms but loops 15288 times (that's actually the number of records in the referenced table), which in my book makes this scan take up to 8 x 15288 = 122304 ms or 122 seconds work_mem is set to 50MB and increasing it to 80MB makes no difference > > Thanks, > > Stephen > > > 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
* Uwe Schroeder (uwe@oss4u.com) wrote:
> Yes, the database is vacuumed and analyzed. The bad plan from 9.0 improves by
> 2 seconds when I go for a really high statistics target of 5000.
What if you go back to 10..?
Stephen
Attachment
<del> > 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. Usually someone here has a lot more knowledge than me and comes up with a viable hint rather quickly. Not so this time I'm afraid. That tells me that something deep down changed. Here are a few observations I made: in PG9 NOT IN queries with a subselect (aka "select x from y where x.id not in (select id from some_other_table)" ) perform a heck of a lot better than in 8.x. On the same note, when you re-wrote the query to use a left outer join with a "IS NULL" where clause, PG9 performs horribly slow. A query like "select x from y left outer join z on z.id=y.id where z.id is null" performs like a 1000 times slower than in 8.x I'm not an expert looking at explain output, but every time I try the "left outer" solution to something that's basically a "not in" I get lousy performace. Looking at the explain, now a "left outer join" always implies as many loops over a nested block as there are rows in the referenced table. 8.x actually returns the rows in one loop. This seems to be an issue of what is done in what order. 8.x puts the "left outer" scan pretty early in the query, so the remaining joins already use a limited dataset. 9.0 puts the left outer towards the end of the nested blocks, which makes it work on the full set. Maybe this makes sense to someone with more in-depth knowlege of the changes. So far to me it looks like "if you use 9.x, avoit left outer joins and use "NOT IN". On pg versions prior to 9.x avoid NOT IN and use left outer joins odd :-) Uwe