Re: Performance problems with 9.2.15

From: Johan Fredriksson <eskil(at)kth(dot)se>
To: pgsql-performance(at)postgresql(dot)org
Subject: Re: Performance problems with 9.2.15
Date: 2016-05-30 13:56:58
Message-ID: 1464616618.19212.3.camel@kth.se
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-performance

> > The rowcount estimates from 9.2 seem greatly different from the 8.4 plan.
> > Did you remember to ANALYZE all the tables after migrating? Maybe there
> > were some table-specific statistics targets that you forgot to transfer
> > over? In any case, the 9.2 plan looks like garbage-in-garbage-out to
> > me :-( ... without estimates at least a little closer to reality, the
> > planner is unlikely to do anything very sane.
> >
> > (BTW, I wonder why you are moving only to 9.2 and not something more
> > recent.)
>
> You put me on the right track with your conclusion that the estimates
> were off the chart. The quick-and-dirty fix "DELETE FROM pg_statistic;"
> solved this problem. This database now have to build up sane estimates
> from scratch.

Actually it took a VACUUM FULL; and DELETE FROM pg_statistic; followed
by ANALYZE on all tables to get it right.

Can someone please explain to me the difference between these two query
plans:

The bad one:
Unique (cost=6037.10..6037.18 rows=1 width=434) (actual
time=255608.588..255646.828 rows=572 loops=1)
-> Sort (cost=6037.10..6037.11 rows=1 width=434) (actual
time=255608.583..255611.632 rows=33209 loops=1)
Sort Method: quicksort Memory: 13143kB
-> Nested Loop (cost=42.51..6037.09 rows=1 width=434) (actual
time=152.818..254886.674 rows=33209 loops=1)
Join Filter: (cachedgroupmembers_4.groupid =
acl_3.principalid)
Rows Removed by Join Filter: 495425041
-> Bitmap Heap Scan on public.acl acl_3
(cost=30.07..144.35 rows=497 width=4) (actual time=0.284..8.184 rows=525
loops=1)
Recheck Cond: ((((acl_3.rightname)::text =
'OwnTicket'::text) AND ((acl_3.principaltype)::text = 'Group'::text)) OR
(((acl_3.rightname)::text = 'SuperUser'::text) AND
((acl_3.principaltype):
:text = 'Group'::text)))
Filter: (((acl_3.objecttype)::text =
'RT::Queue'::text) OR (((acl_3.objecttype)::text = 'RT::System'::text)
AND (acl_3.objectid = 1)))
-> BitmapOr (cost=30.07..30.07 rows=531 width=0)
(actual time=0.249..0.249 rows=0 loops=1)
-> Bitmap Index Scan on acl1
(cost=0.00..25.46 rows=521 width=0) (actual time=0.233..0.233 rows=521
loops=1)
Index Cond: (((acl_3.rightname)::text =
'OwnTicket'::text) AND ((acl_3.principaltype)::text = 'Group'::text))
-> Bitmap Index Scan on acl1
(cost=0.00..4.36 rows=11 width=0) (actual time=0.016..0.016 rows=4
loops=1)
Index Cond: (((acl_3.rightname)::text =
'SuperUser'::text) AND ((acl_3.principaltype)::text = 'Group'::text))
-> Materialize (cost=12.44..5870.39 rows=3 width=438)
(actual time=0.004..176.296 rows=943730 loops=525)
-> Nested Loop (cost=12.44..5870.37 rows=3
width=438) (actual time=0.351..1028.683 rows=943730 loops=1)
-> Nested Loop (cost=12.44..5601.49 rows=2
width=442) (actual time=0.326..15.591 rows=675 loops=1)
-> Nested Loop (cost=12.44..5502.26
rows=27 width=8) (actual time=0.303..9.744 rows=675 loops=1)
Output: principals_1.id,
cachedgroupmembers_2.memberid
-> Bitmap Heap Scan on
public.cachedgroupmembers cachedgroupmembers_2 (cost=12.44..1659.12
rows=446 width=4) (actual time=0.267..1.266 rows=676 loops=1)

Recheck Cond: (cachedgroupmembers_2.groupid = 4)
Filter:
(cachedgroupmembers_2.disabled = 0)
-> Bitmap Index Scan on
cachedgroupmembers2 (cost=0.00..12.33 rows=446 width=0) (actual
time=0.171..0.171 rows=676 loops=1)
Index Cond:
(cachedgroupmembers_2.groupid = 4)
-> Index Scan using
principals_pkey on public.principals principals_1 (cost=0.00..8.61
rows=1 width=4) (actual time=0.011..0.011 rows=1 loops=676)
Output: principals_1.id
Index Cond:
(principals_1.id = cachedgroupmembers_2.memberid)
Filter: ((principals_1.id
<> 1) AND (principals_1.disabled = 0) AND
((principals_1.principaltype)::text = 'User'::text))
Rows Removed by Filter: 0
-> Index Scan using users_pkey on
public.users main (cost=0.00..3.67 rows=1 width=434) (actual
time=0.007..0.008 rows=1
loops=675)
Index Cond: (main.id =
principals_1.id)
-> Index Scan using cachedgroupmembers1 on
public.cachedgroupmembers cachedgroupmembers_4 (cost=0.00..133.79
rows=65 width=8) (actual time=0.012..1.199 rows=1398 loops=675)

Index Cond:
(cachedgroupmembers_4.memberid = principals_1.id)
Filter: (cachedgroupmembers_4.disabled
= 0)
Rows Removed by Filter: 0
Total runtime: 255694.440 ms
(47 rows)

The good one:
Unique (cost=528.88..528.96 rows=1 width=522) (actual
time=5029.906..5068.395 rows=572 loops=1)
-> Sort (cost=528.88..528.89 rows=1 width=522) (actual
time=5029.889..5032.743 rows=33209 loops=1)
Sort Method: quicksort Memory: 13143kB
-> Nested Loop (cost=36.08..528.87 rows=1 width=522) (actual
time=0.410..4178.931 rows=33209 loops=1)
-> Nested Loop (cost=3.54..449.25 rows=2 width=526)
(actual time=0.139..1459.785 rows=943730 loops=1)
Join Filter: (principals_1.id =
cachedgroupmembers_4.memberid)
-> Nested Loop (cost=0.00..314.65 rows=1
width=530) (actual time=0.115..12.537 rows=675 loops=1)
-> Nested Loop (cost=0.00..310.98 rows=1
width=8) (actual time=0.106..7.203 rows=675 loops=1)
Output: principals_1.id,
cachedgroupmembers_2.memberid
-> Index Only Scan using disgroumem on
public.cachedgroupmembers cachedgroupmembers_2 (cost=0.00..101.59
rows=24 width=4) (actual time=0.071..1.046 rows=676 loops=1)
Output:
cachedgroupmembers_2.groupid, cachedgroupmembers_2.memberid,
cachedgroupmembers_2.disabled
Index Cond:
((cachedgroupmembers_2.groupid = 4) AND (cachedgroupmembers_2.disabled =
0))
Heap Fetches: 676
-> Index Scan using principals_pkey on
public.principals principals_1 (cost=0.00..8.71 rows=1 width=4) (actual
time=0.008..0.008 rows=1 loops=676)
Output: principals_1.id
Index Cond: (principals_1.id =
cachedgroupmembers_2.memberid)
Filter: ((principals_1.id <> 1)
AND (principals_1.disabled = 0) AND ((principals_1.principaltype)::text
= 'User'::text))
Rows Removed by Filter: 0
-> Index Scan using users_pkey on
public.users main (cost=0.00..3.67 rows=1 width=522) (actual
time=0.006..0.007 rows=1 loops=675)
Index Cond: (main.id = principals_1.id)
-> Bitmap Heap Scan on public.cachedgroupmembers
cachedgroupmembers_4 (cost=3.54..133.77 rows=66 width=8) (actual
time=0.309..1.752 rows=1398 loops=675)
Recheck Cond: (cachedgroupmembers_4.memberid
= main.id)
Filter: (cachedgroupmembers_4.disabled = 0)
Rows Removed by Filter: 0
-> Bitmap Index Scan on cachedgroupmembers1
(cost=0.00..3.52 rows=66 width=0) (actual time=0.185..0.185 rows=1398
loops=675)
Index Cond:
(cachedgroupmembers_4.memberid = main.id)
-> Bitmap Heap Scan on public.acl acl_3
(cost=32.54..39.78 rows=3 width=4) (actual time=0.002..0.002 rows=0
loops=943730)
Recheck Cond: ((acl_3.principalid =
cachedgroupmembers_4.groupid) AND ((((acl_3.rightname)::text =
'OwnTicket'::text) AND ((acl_3.principaltype)::text = 'Group'::text)) OR
(((acl_3.rightname
)::text = 'SuperUser'::text) AND ((acl_3.principaltype)::text =
'Group'::text))))
Filter: (((acl_3.objecttype)::text =
'RT::Queue'::text) OR (((acl_3.objecttype)::text = 'RT::System'::text)
AND (acl_3.objectid = 1)))
-> BitmapAnd (cost=32.54..32.54 rows=3 width=0)
(actual time=0.002..0.002 rows=0 loops=943730)
-> Bitmap Index Scan on acl3
(cost=0.00..2.22 rows=49 width=0) (actual time=0.001..0.001 rows=1
loops=943730)
Index Cond: (acl_3.principalid =
cachedgroupmembers_4.groupid)
-> BitmapOr (cost=30.07..30.07 rows=531
width=0) (actual time=0.110..0.110 rows=0 loops=4412)
-> Bitmap Index Scan on acl1
(cost=0.00..25.46 rows=521 width=0) (actual time=0.102..0.102 rows=521
loops=4412)
Index Cond:
(((acl_3.rightname)::text = 'OwnTicket'::text) AND
((acl_3.principaltype)::text = 'Group'::text))
-> Bitmap Index Scan on acl1
(cost=0.00..4.36 rows=11 width=0) (actual time=0.007..0.007 rows=4
loops=4412)
Index Cond:
(((acl_3.rightname)::text = 'SuperUser'::text) AND
((acl_3.principaltype)::text = 'Group'::text))
Total runtime: 5069.842 ms
(47 rows)

Why does PostgreSQL pick one before the other and how can I make sure
that it will keep using the "good" one instead of the "bad" one?

/ Eskil

In response to

Responses

Browse pgsql-performance by date

  From Date Subject
Next Message Vladimir Borodin 2016-05-30 14:53:55 Re: 9.4 -> 9.5 regression with queries through pgbouncer on RHEL 6
Previous Message Johan Fredriksson 2016-05-30 07:35:29 Re: Performance problems with 9.2.15