Thread: 8.2.4 Chooses Bad Query Plan

Hi,

    We have recently upgraded our production database from 8.0.12 to
8.2.4, We have seen lot of improvements on 8.2.4 side but we are also
seeing some queries which are slow.

    Particularly this below query is really bad in 8.2.4 , I can get
only the explain on this as explain analyze never finishes even after 20
min.
    8.2.4 plan uses this index which is pretty much doing a full index
scan on 52mill records and I think that is taking lot of time to
execute. Where as 8.0.12 doesnt use this index in the plan.

     ->  Index Scan Backward using pk_activity_activityid on activity
activity1_  (cost=0.00..1827471.18 rows=52363227 width=8)

    I have also pasted the 8.0.12 explain analyze output which takes
little over a min , I can live with that.
    All the related tables in 8.2.4 are vacuumed and analyzed thru
autovacuum utility.

    Can anyone tell why the 8.2.4 plan is bad for this query ? Is this
expected behavior in 8.2.4 ?

Thanks!
Pallav.

Hardware
-------------
OS: Open Suse 10.1
Memory: 8gb
CPU: 2 (Dual Core).

Postgres Settings
----------------------
shared_buffers = 1GB
work_mem = 32MB
maintenance_work_mem = 256MB
effective_cache_size = 6400MB

8.2.4 Plan
=======
explain
select accountact0_.accountactivityid as accounta1_46_,
accountact0_.fkaccountid as fkaccoun2_46_,
          accountact0_.fkserviceinstanceid as fkservic3_46_,
accountact0_.fkactivityid as fkactivi4_46_
from provisioning.accountactivity accountact0_, common.activity
activity1_, common.activitytype activityty2_
where accountact0_.fkactivityid=activity1_.activityId
and activity1_.fkactivitytypeid=activityty2_.activitytypeid
and accountact0_.fkaccountid= 1455437
and activityty2_.name='UNLOCK_ACCOUNT'
order by activity1_.activityid desc
limit 1;
                                                                QUERY PLAN

------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=3.43..57381.12 rows=1 width=20)
   ->  Nested Loop  (cost=3.43..4819729.72 rows=84 width=20)
         ->  Nested Loop  (cost=3.43..3005647.22 rows=459327 width=4)
               Join Filter: (activity1_.fkactivitytypeid =
activityty2_.activitytypeid)
               ->  Index Scan Backward using pk_activity_activityid on
activity activity1_  (cost=0.00..1827471.18 rows=52363227 width=8)
               ->  Materialize  (cost=3.43..3.44 rows=1 width=4)
                     ->  Seq Scan on activitytype activityty2_
(cost=0.00..3.42 rows=1 width=4)
                           Filter: (name = 'UNLOCK_ACCOUNT'::text)
         ->  Index Scan using idx_accountactivity_fkactivityid on
accountactivity accountact0_  (cost=0.00..3.94 rows=1 width=16)
               Index Cond: (accountact0_.fkactivityid =
activity1_.activityid)
               Filter: (fkaccountid = 1455437)
(11 rows)


8.0.12 Plan
========
explain analyze
select accountact0_.accountactivityid as accounta1_46_,
accountact0_.fkaccountid as fkaccoun2_46_,
          accountact0_.fkserviceinstanceid as fkservic3_46_,
accountact0_.fkactivityid as fkactivi4_46_
from provisioning.accountactivity accountact0_, common.activity
activity1_, common.activitytype activityty2_
where accountact0_.fkactivityid=activity1_.activityId
and activity1_.fkactivitytypeid=activityty2_.activitytypeid
and accountact0_.fkaccountid= 1455437
and activityty2_.name='UNLOCK_ACCOUNT'
order by activity1_.activityid desc
limit 1;

QUERY PLAN

-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=5725.89..5725.89 rows=1 width=20) (actual
time=64555.895..64555.895 rows=0 loops=1)
   ->  Sort  (cost=5725.89..5725.92 rows=12 width=20) (actual
time=64555.893..64555.893 rows=0 loops=1)
         Sort Key: activity1_.activityid
         ->  Nested Loop  (cost=0.00..5725.67 rows=12 width=20) (actual
time=64555.730..64555.730 rows=0 loops=1)
               Join Filter: ("inner".fkactivitytypeid =
"outer".activitytypeid)
               ->  Seq Scan on activitytype activityty2_
(cost=0.00..3.42 rows=1 width=4) (actual time=8.670..8.691 rows=1 loops=1)
                     Filter: (name = 'UNLOCK_ACCOUNT'::text)
               ->  Nested Loop  (cost=0.00..5705.46 rows=1343 width=24)
(actual time=282.550..64539.423 rows=10302 loops=1)
                     ->  Index Scan using
idx_accountactivity_fkaccountid on accountactivity accountact0_
(cost=0.00..1641.42 rows=1343 width=16) (actual time=115.348..864.416
rows=10302 loops=1)
                           Index Cond: (fkaccountid = 1455437)
                     ->  Index Scan using pk_activity_activityid on
activity activity1_  (cost=0.00..3.01 rows=1 width=8) (actual
time=6.177..6.178 rows=1 loops=10302)
                           Index Cond: ("outer".fkactivityid =
activity1_.activityid)
 Total runtime: 64555.994 ms
(13 rows)

Table Definitions
===========

 #\d provisioning.accountactivity
                                     Table "provisioning.accountactivity"
       Column        |  Type   |                                   Modifiers
---------------------+---------+-------------------------------------------------------------------------------
 accountactivityid   | integer | not null default
nextval(('provisioning.AccountActivitySeq'::text)::regclass)
 fkaccountid         | integer | not null
 fkactivityid        | integer | not null
 fkserviceinstanceid | integer |
Indexes:
    "pk_accountactivity_accountactivityid" PRIMARY KEY, btree
(accountactivityid), tablespace "indexdata"
    "idx_accountactivity_fkaccountid" btree (fkaccountid), tablespace
"indexdata"
    "idx_accountactivity_fkactivityid" btree (fkactivityid), tablespace
"indexdata"
Foreign-key constraints:
    "fk_accountactivity_account" FOREIGN KEY (fkaccountid) REFERENCES
provisioning.account(accountid)
    "fk_accountactivity_activity" FOREIGN KEY (fkactivityid) REFERENCES
common.activity(activityid)
    "fk_accountactivity_serviceinstance" FOREIGN KEY
(fkserviceinstanceid) REFERENCES
provisioning.serviceinstance(serviceinstanceid)

# \d common.activity
                                              Table "common.activity"
      Column      |            Type
|                            Modifiers
------------------+-----------------------------+------------------------------------------------------------------
 activityid       | integer                     | not null default
nextval(('common.ActivitySeq'::text)::regclass)
 createdate       | timestamp without time zone | not null default
('now'::text)::timestamp(6) without time zone
 fkactivitytypeid | integer                     | not null
 extra            | text                        |
 ipaddress        | text                        |
Indexes:
    "pk_activity_activityid" PRIMARY KEY, btree (activityid), tablespace
"indexdata"
    "idx_activity_createdate" btree (createdate), tablespace "indexdata"
Foreign-key constraints:
    "fk_activity_activitytype" FOREIGN KEY (fkactivitytypeid) REFERENCES
common.activitytype(activitytypeid)

# \d common.activitytype
                                   Table "common.activitytype"
     Column     |  Type   |                              Modifiers
----------------+---------+----------------------------------------------------------------------
 activitytypeid | integer | not null default
nextval(('common.ActivityTypeSeq'::text)::regclass)
 name           | text    | not null
 description    | text    |
 displayname    | text    |
Indexes:
    "pk_activitytype_activitytypeid" PRIMARY KEY, btree
(activitytypeid), tablespace "indexdata"
    "uq_activitytype_name" UNIQUE, btree (name), tablespace "indexdata"

Pallav Kalva <pkalva@livedatagroup.com> writes:
>     We have recently upgraded our production database from 8.0.12 to
> 8.2.4, We have seen lot of improvements on 8.2.4 side but we are also
> seeing some queries which are slow.

>     Particularly this below query is really bad in 8.2.4 , I can get
> only the explain on this as explain analyze never finishes even after 20
> min.

What it's doing is scanning backward on activity1_.activityid and hoping
to find a row that matches all the other constraints soon enough to make
that faster than any other way of doing the query.  8.0 would have done
the same thing, I believe, if the statistics looked favorable for it.
So I wonder if you've forgotten to re-ANALYZE your data since migrating
(a pg_dump script won't do this for you).

>          ->  Index Scan using idx_accountactivity_fkactivityid on
> accountactivity accountact0_  (cost=0.00..3.94 rows=1 width=16)
>                Index Cond: (accountact0_.fkactivityid =
> activity1_.activityid)
>                Filter: (fkaccountid = 1455437)

>                      ->  Index Scan using
> idx_accountactivity_fkaccountid on accountactivity accountact0_
> (cost=0.00..1641.42 rows=1343 width=16) (actual time=115.348..864.416
> rows=10302 loops=1)
>                            Index Cond: (fkaccountid = 1455437)

The discrepancy in rowcount estimates here is pretty damning.
Even the 8.0 estimate wasn't really very good --- you might want to
consider increasing default_statistics_target.

            regards, tom lane

Hi Tom,

   Thanks! for the reply, see my comments below

Tom Lane wrote:
> Pallav Kalva <pkalva@livedatagroup.com> writes:
>
>>     We have recently upgraded our production database from 8.0.12 to
>> 8.2.4, We have seen lot of improvements on 8.2.4 side but we are also
>> seeing some queries which are slow.
>>
>
>
>>     Particularly this below query is really bad in 8.2.4 , I can get
>> only the explain on this as explain analyze never finishes even after 20
>> min.
>>
>
> What it's doing is scanning backward on activity1_.activityid and hoping
> to find a row that matches all the other constraints soon enough to make
> that faster than any other way of doing the query.  8.0 would have done
> the same thing, I believe, if the statistics looked favorable for it.
> So I wonder if you've forgotten to re-ANALYZE your data since migrating
> (a pg_dump script won't do this for you).
>
>

So, if I understand this correctly it keeps doing index scan backwards
until it finds
a matching record , if it cant find any record it pretty much scans the
whole table
using "index scan backward" ?

If I have no matching record I pretty much wait until the query
finishes  ?

Is there anything else I can do to improve the query ?

I have analyzed tables again and also my default_stats_target is set to
100,
still it shows the same plan.

>>          ->  Index Scan using idx_accountactivity_fkactivityid on
>> accountactivity accountact0_  (cost=0.00..3.94 rows=1 width=16)
>>                Index Cond: (accountact0_.fkactivityid =
>> activity1_.activityid)
>>                Filter: (fkaccountid = 1455437)
>>
>
>
>>                      ->  Index Scan using
>> idx_accountactivity_fkaccountid on accountactivity accountact0_
>> (cost=0.00..1641.42 rows=1343 width=16) (actual time=115.348..864.416
>> rows=10302 loops=1)
>>                            Index Cond: (fkaccountid = 1455437)
>>
>
> The discrepancy in rowcount estimates here is pretty damning.
> Even the 8.0 estimate wasn't really very good --- you might want to
> consider increasing default_statistics_target.
>
>             regards, tom lane
>
> ---------------------------(end of broadcast)---------------------------
> TIP 6: explain analyze is your friend
>

Pallav Kalva <pkalva@livedatagroup.com> writes:
> I have analyzed tables again and also my default_stats_target is set to
> 100, still it shows the same plan.

>>> ->  Index Scan using idx_accountactivity_fkactivityid on
>>> accountactivity accountact0_  (cost=0.00..3.94 rows=1 width=16)
>>> Index Cond: (accountact0_.fkactivityid =
>>> activity1_.activityid)
>>> Filter: (fkaccountid = 1455437)

>>> ->  Index Scan using
>>> idx_accountactivity_fkaccountid on accountactivity accountact0_
>>> (cost=0.00..1641.42 rows=1343 width=16) (actual time=115.348..864.416
>>> rows=10302 loops=1)
>>> Index Cond: (fkaccountid = 1455437)

Oh, my bad, I failed to look closely enough at these subplans.
I thought they were identical but they're not using the same scan
conditions, so the rowcount estimates shouldn't be comparable after all.

Could you try EXPLAINing (maybe even with ANALYZE) the query *without*
the LIMIT clause?  I'm curious to see what it thinks the best plan is
then.

            regards, tom lane