Thread: Chaotically weird execution plan

When displaying information about information about an user in our
site, I noticed an unreasonable slowdown. The culprit turned out to be
a trivial select, which determines the number of comments left by an
user:

select count(*) from comments where created_by=80 and status=1;


The comments table structure is below, and contains ~2 million
records. I guess postgresql is unable to figure out exactly how to
make use of the index condition? As query plan shows, it got the
correct answer, 15888, very fast: the rest of the 13 seconds it's just
rechecking all the comments for some weird reasons. The weird thing
is, SOMETIMES, for other created_by values, it seems to work fine, as
shown below as well. Is this a bug, or I'm missing something here?

Thanks,
Einars Lielmanis



*** worse plan example:

etests=> explain analyze select count(*) from comments where
created_by=80 and status=1;

QUERY PLAN

----------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=50947.51..50947.52 rows=1 width=0) (actual
time=13134.360..13134.361 rows=1 loops=1)
   ->  Bitmap Heap Scan on comments  (cost=331.42..50898.41 rows=19639
width=0) (actual time=40.865..13124.116 rows=15888 loops=1)
         Recheck Cond: ((created_by = 80) AND (status = 1))
         ->  Bitmap Index Scan on comments_created_by
(cost=0.00..326.51 rows=19639 width=0) (actual time=33.547..33.547
rows=15888 loops=1)
               Index Cond: (created_by = 80)
 Total runtime: 13134.688 ms



*** better plan example:

etests=> explain analyze select count(*) from comments where
created_by=81 and status=1;
                                                               QUERY PLAN

----------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=854.10..854.11 rows=1 width=0) (actual
time=0.083..0.083 rows=1 loops=1)
   ->  Index Scan using comments_created_by on comments
(cost=0.00..853.44 rows=262 width=0) (actual time=0.057..0.076 rows=3
loops=1)
         Index Cond: (created_by = 81)
 Total runtime: 0.121 ms



*** structure

etests=> \d comments;
                                            Table "public.comments"
     Column      |            Type             |
    Modifiers
-----------------+-----------------------------+---------------------------------------------------------------
 comment_id      | integer                     | not null default
nextval('comments_comment_id_seq'::regclass)
 message_wiki    | text                        |
 message_html    | text                        |
 status          | integer                     |
 post_id         | integer                     |
 created         | timestamp without time zone |
 created_by      | integer                     |

Indexes:
    "comments_pkey" PRIMARY KEY, btree (comment_id)
    "comments_created_by" btree (created_by) WHERE status = 1
    "comments_for_post" btree (post_id, created) WHERE status = 1
Check constraints:
    "comments_status_check" CHECK (status = ANY (ARRAY[0, 1, 2]))
Foreign-key constraints:
    "comments_created_by_fkey" FOREIGN KEY (created_by) REFERENCES
members(member_id)
    "comments_thread_id_fkey" FOREIGN KEY (post_id) REFERENCES posts(post_id)

PostgreSQL 8.3.1 on i686-pc-linux-gnu, compiled by GCC gcc (GCC) 4.2.3
(Ubuntu 4.2.3-2ubuntu7)

Einars wrote:
> As query plan shows, it got the
> correct answer, 15888, very fast: the rest of the 13 seconds it's just
> rechecking all the comments for some weird reasons.

I'd already written: "If you need the test for status = 1, consider a
partial index" when I noticed your schema definition:

>     "comments_created_by" btree (created_by) WHERE status = 1

I find it hard to guess why it's having to recheck the WHERE clause
given the use of a partial index that should cover that nicely. I don't
see how it could be a visibility issue (in that I thought tuples were
read and tested for visibility as part of the initial heap scan) but I
don't see what else it could be.

It seems odd to me, so I'm really interested in seeing what others have
to say on this.

--
Craig Ringer

Einars <einars@gmail.com> writes:
> When displaying information about information about an user in our
> site, I noticed an unreasonable slowdown. The culprit turned out to be
> a trivial select, which determines the number of comments left by an
> user:

I don't see anything even slightly wrong here.  Your first example pulls
15888 rows from the table in 13134 ms.  Your second example pulls 3
rows from the table in 0.121 ms --- which I rather imagine is because
those three rows are already in cache; it would take a lot longer if it
actually had to go to disk several times.

The planner's rowcount estimates are on target and it appears to be
choosing appropriate plans in each case.  It just takes longer to
process 5000 times as many rows ...

            regards, tom lane

Craig Ringer <craig@postnewspapers.com.au> writes:
> I'd already written: "If you need the test for status = 1, consider a
> partial index" when I noticed your schema definition:

>> "comments_created_by" btree (created_by) WHERE status = 1

> I find it hard to guess why it's having to recheck the WHERE clause
> given the use of a partial index that should cover that nicely.

No, that's operating as designed.  A bitmap scan's RECHECK condition
is only applied when the bitmap has become lossy due to memory
pressure.  In that case we have to look at each row on each of the pages
fingered by the index as containing possible matches ... and we'd better
check the partial-index qual too, since maybe not all the rows on those
pages will satisfy it.  In a plain indexscan there is no lossiness
involved and so the partial-index qual need never be rechecked.

            regards, tom lane

Tom Lane wrote:
> Craig Ringer <craig@postnewspapers.com.au> writes:
>> I'd already written: "If you need the test for status = 1, consider a
>> partial index" when I noticed your schema definition:
>
>>> "comments_created_by" btree (created_by) WHERE status = 1
>
>> I find it hard to guess why it's having to recheck the WHERE clause
>> given the use of a partial index that should cover that nicely.
>
> No, that's operating as designed.  A bitmap scan's RECHECK condition
> is only applied when the bitmap has become lossy due to memory
> pressure.  In that case we have to look at each row on each of the pages
> fingered by the index as containing possible matches ... and we'd better
> check the partial-index qual too, since maybe not all the rows on those
> pages will satisfy it.  In a plain indexscan there is no lossiness
> involved and so the partial-index qual need never be rechecked.

Aah. Thanks very much for the explanation of that, the plan now makes sense.

--
Craig Ringer