Search Postgresql Archives

Re: PG9.0 planner difference to 8.3 -> majorly bad performance

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 




> On 29 January 2011 09:11, Uwe Schroeder <uwe@xxxxxxxxx> 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.






-- 
Sent via pgsql-general mailing list (pgsql-general@xxxxxxxxxxxxxx)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general


[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
[Index of Archives]     [Postgresql Jobs]     [Postgresql Admin]     [Postgresql Performance]     [Linux Clusters]     [PHP Home]     [PHP on Windows]     [Kernel Newbies]     [PHP Classes]     [PHP Books]     [PHP Databases]     [Postgresql & PHP]     [Yosemite]
  Powered by Linux