Thread: Slow query when joining to un-analyzed temp table...

Sorry for the bulky transcript here, but I don't see a better way to
convey what's going on.  I hope someone will take a look anyway.  It's
attached as well to preserve line breaks, or the lack thereof.

Before I begin, yes the DB is well vacummed/analyzed :-)

I have a query that appears to plan out correctly, in terms of index
use, and produces only 13 rows, but is still slow (over a second for a
query that should take ~0.0 time).  The index it uses *should* also
produce 13 rows (and in other tests it does produce 13 rows).

The funky queries are commented below...

TIA,
Glen Parker
glenebob@nwlink.com
----------------------------------------------------

oms=# select version();
                           version
-------------------------------------------------------------
 PostgreSQL 7.2.1 on i686-pc-linux-gnu, compiled by GCC 2.96
(1 row)

oms=# create temp table __item_id as select item_id from items where
branch='10' and date_modified >= '09/01/2002';
SELECT

oms=# select count(*) from __item_id;
 count
-------
     4
(1 row)

oms=# select count(*) from itemindex;
 count
-------
 66072
(1 row)



/*
  HERE IS WHERE THE TROUBLE STARTS...
  Why does the index scan claim to have found 57387 rows?  It *should*
find 13, and this step should
  naturally then be quite fast, but it appears that this step is what
takes all the time.
*/
oms=# explain analyze select i.* from itemindex i, __item_id l where
i.item_id = l.item_id order by i.item_id,i.seq;
NOTICE:  QUERY PLAN:

Sort  (cost=4117.20..4117.20 rows=2107 width=54) (actual
time=1060.14..1060.16 rows=13 loops=1)
  ->  Merge Join  (cost=69.83..4000.90 rows=2107 width=54) (actual
time=0.73..1059.79 rows=13 loops=1)
        ->  Index Scan using idx_itemindex_itemid on itemindex i
(cost=0.00..3737.06 rows=66072 width=50) (actual time=0.37..915.49
rows=57387 loops=1)
        ->  Sort  (cost=69.83..69.83 rows=1000 width=4) (actual
time=0.12..0.14 rows=9 loops=1)
              ->  Seq Scan on __item_id l  (cost=0.00..20.00 rows=1000
width=4) (actual time=0.01..0.03 rows=4 loops=1)
Total runtime: 1060.46 msec

EXPLAIN

oms=# select i.* from itemindex i, __item_id l where i.item_id =
l.item_id order by i.item_id,i.seq;
<DATA SNIPPED>
(13 rows)

oms=# analyze __item_id;
ANALYZE



/*
  HUH?
  Analyzing a 4 row table makes a real difference??  The query does a
seq-scan on the temp table
  whether its been analyzed or not.  This is a temp table; trying to
write portable
  SQL dictates that I can't use an analyze here.
*/
oms=# explain analyze select i.* from itemindex i, __item_id l where
i.item_id = l.item_id order by i.item_id,i.seq;
NOTICE:  QUERY PLAN:

Sort  (cost=40.30..40.30 rows=8 width=54) (actual time=1.02..1.03
rows=13 loops=1)
  ->  Nested Loop  (cost=0.00..40.17 rows=8 width=54) (actual
time=0.11..0.82 rows=13 loops=1)
        ->  Seq Scan on __item_id l  (cost=0.00..1.04 rows=4 width=4)
(actual time=0.02..0.04 rows=4 loops=1)
        ->  Index Scan using idx_itemindex_itemid on itemindex i
(cost=0.00..9.76 rows=2 width=50) (actual time=0.05..0.15 rows=3
loops=4)
Total runtime: 1.25 msec

EXPLAIN

On Fri, 6 Sep 2002, Glen Parker wrote:

> oms=# create temp table __item_id as select item_id from items where
> branch='10' and date_modified >= '09/01/2002';
> SELECT
>
> oms=# select count(*) from __item_id;
>  count
> -------
>      4
> (1 row)
>
> oms=# select count(*) from itemindex;
>  count
> -------
>  66072
> (1 row)
>
>
>
> /*
>   HERE IS WHERE THE TROUBLE STARTS...
>   Why does the index scan claim to have found 57387 rows?  It *should*
> find 13, and this step should
>   naturally then be quite fast, but it appears that this step is what
> takes all the time.
> */

Well, this query plan thinks there are 1000 output rows from the
__item_id scan, and the lower one thinks there are 4.  In the first
it's attempting a merge join between the two results which possibly would
be better if there really were 1000 rows in __item_id.  I don't
really know, but I'd guess the 57387 is how many rows it got through
before running off the last row in __item_id in the merge.

> oms=# explain analyze select i.* from itemindex i, __item_id l where
> i.item_id = l.item_id order by i.item_id,i.seq;
> NOTICE:  QUERY PLAN:
>
> Sort  (cost=4117.20..4117.20 rows=2107 width=54) (actual
> time=1060.14..1060.16 rows=13 loops=1)
>   ->  Merge Join  (cost=69.83..4000.90 rows=2107 width=54) (actual
> time=0.73..1059.79 rows=13 loops=1)
>         ->  Index Scan using idx_itemindex_itemid on itemindex i
> (cost=0.00..3737.06 rows=66072 width=50) (actual time=0.37..915.49
> rows=57387 loops=1)
>         ->  Sort  (cost=69.83..69.83 rows=1000 width=4) (actual
> time=0.12..0.14 rows=9 loops=1)
>               ->  Seq Scan on __item_id l  (cost=0.00..20.00 rows=1000
> width=4) (actual time=0.01..0.03 rows=4 loops=1)
> Total runtime: 1060.46 msec
>
> EXPLAIN
>
> oms=# select i.* from itemindex i, __item_id l where i.item_id =
> l.item_id order by i.item_id,i.seq;
> <DATA SNIPPED>
> (13 rows)
>
> oms=# analyze __item_id;
> ANALYZE
>
>
> /*
>   HUH?
>   Analyzing a 4 row table makes a real difference??  The query does a
> seq-scan on the temp table
>   whether its been analyzed or not.  This is a temp table; trying to
> write portable
>   SQL dictates that I can't use an analyze here.
> */
> oms=# explain analyze select i.* from itemindex i, __item_id l where
> i.item_id = l.item_id order by i.item_id,i.seq;
> NOTICE:  QUERY PLAN:
>
> Sort  (cost=40.30..40.30 rows=8 width=54) (actual time=1.02..1.03
> rows=13 loops=1)
>   ->  Nested Loop  (cost=0.00..40.17 rows=8 width=54) (actual
> time=0.11..0.82 rows=13 loops=1)
>         ->  Seq Scan on __item_id l  (cost=0.00..1.04 rows=4 width=4)
> (actual time=0.02..0.04 rows=4 loops=1)
>         ->  Index Scan using idx_itemindex_itemid on itemindex i
> (cost=0.00..9.76 rows=2 width=50) (actual time=0.05..0.15 rows=3
> loops=4)
> Total runtime: 1.25 msec
>
> EXPLAIN
>
>