Thread: order by slowing down a query by 80 times

Rajesh Kumar Mallah wrote:
> Dear List,
>
> just by removing the order by co_name reduces the query time dramatically
> from  ~ 9 sec  to 63 ms. Can anyone please help.
The 63 ms query result is probably useless since it returns a limit of
25 rows from an unordered result. It is not surprising that this is fast.

The pain is here:
Index Scan using profile_master_co_name on profile_master b
(cost=0.00..1125295.59 rows=6968 width=25) (actual time=0.097..9193.154
rows=2212 loops=1)
                                 Filter: ((co_name IS NOT NULL) AND
((co_name_vec)::tsvector @@ to_tsquery('manufacturer'::text)))


It looks like seq_scans are disabled, since the index scan has only a
filter expression but not an index cond.

regards,
Yeb Havinga

>
> Regds
> Rajesh Kumar Mallah.
>
>
> explain analyze SELECT * from   ( SELECT
> a.profile_id,a.userid,a.amount,a.category_id,a.catalog_id,a.keywords,b.co_name
> from general.catalogs a join general.profile_master using(profile_id)
> where  1=1  and co_name_vec @@   to_tsquery('manufacturer')  and
> b.co_name is not null and a.ifmain is true ) as c order by co_name
> limit 25 offset 0;
>
>
> Limit  (cost=0.00..3659.13 rows=25 width=129) (actual
> time=721.075..9241.105 rows=25 loops=1)
>    ->  Nested Loop  (cost=0.00..1215772.28 rows=8307 width=476)
> (actual time=721.073..9241.050 rows=25 loops=1)
>          ->  Nested Loop  (cost=0.00..1208212.37 rows=8307 width=476)
> (actual time=721.052..9240.037 rows=25 loops=1)
>                ->  Nested Loop  (cost=0.00..1204206.26 rows=6968
> width=472) (actual time=721.032..9239.516 rows=25 loops=1)
>                      ->  Nested Loop  (cost=0.00..1154549.19 rows=6968
> width=471) (actual time=721.012..9236.523 rows=25 loops=1)
>                            ->  Index Scan using profile_master_co_name
> on profile_master b  (cost=0.00..1125295.59 rows=6968 width=25)
> (actual time=0.097..9193.154 rows=2212 loops=1)
>                                  Filter: ((co_name IS NOT NULL) AND
> ((co_name_vec)::tsvector @@ to_tsquery('manufacturer'::text)))
>                            ->  Index Scan using
> catalog_master_profile_id_fkindex on catalog_master  (cost=0.00..4.19
> rows=1 width=446) (actual time=0.016..0.016 rows=0 loops=2212)
>                                  Index Cond:
> (catalog_master.profile_id = b.profile_id)
>                                  Filter: ((catalog_master.hide IS
> FALSE) AND ((catalog_master.hosting_status)::text = 'ACTIVE'::text))
>                      ->  Index Scan using
> profile_master_profile_id_pkey on profile_master  (cost=0.00..7.11
> rows=1 width=9) (actual time=0.105..0.105 rows=1 loops=25)
>                            Index Cond: (profile_master.profile_id =
> catalog_master.profile_id)
>                ->  Index Scan using
> catalog_categories_pkey_catalog_id_category_id on catalog_categories
> (cost=0.00..0.56 rows=1 width=8) (actual time=0.014..0.015 rows=1
> loops=25)
>                      Index Cond: (catalog_categories.catalog_id =
> catalog_master.catalog_id)
>                      Filter: (catalog_categories.ifmain IS TRUE)
>          ->  Index Scan using web_category_master_pkey on
> web_category_master  (cost=0.00..0.90 rows=1 width=4) (actual
> time=0.034..0.036 rows=1 loops=25)
>                Index Cond: (web_category_master.category_id =
> catalog_categories.category_id)
>                Filter: ((web_category_master.status)::text =
> 'ACTIVE'::text)
> Total runtime: 9241.304 ms
>
> explain analyze SELECT * from   ( SELECT
> a.profile_id,a.userid,a.amount,a.category_id,a.catalog_id,a.keywords,b.co_name
> from general.catalogs a join general.profile_master b
> using(profile_id) where  1=1  and co_name_vec @@
> to_tsquery('manufacturer')  and  b.co_name is not null and a.ifmain is
> true ) as c  limit 25 offset 0;
>
> QUERY PLAN
>
> ----------------------------------------------------------------------------------------------
>  Limit  (cost=0.00..358.85 rows=25 width=476) (actual
> time=0.680..63.176 rows=25 loops=1)
>    ->  Nested Loop  (cost=0.00..119238.58 rows=8307 width=476) (actual
> time=0.677..63.139 rows=25 loops=1)
>          ->  Nested Loop  (cost=0.00..111678.66 rows=8307 width=476)
> (actual time=0.649..62.789 rows=25 loops=1)
>                ->  Nested Loop  (cost=0.00..107672.56 rows=6968
> width=472) (actual time=0.626..62.436 rows=25 loops=1)
>                      ->  Nested Loop  (cost=0.00..58015.49 rows=6968
> width=471) (actual time=0.606..62.013 rows=25 loops=1)
>                            ->  Index Scan using
> profile_master_co_name_vec on profile_master b  (cost=0.00..28761.89
> rows=6968 width=25) (actual time=0.071..50.576 rows=1160 loops=1)
>                                  Index Cond: ((co_name_vec)::tsvector
> @@ to_tsquery('manufacturer'::text))
>                                  Filter: (co_name IS NOT NULL)
>                            ->  Index Scan using
> catalog_master_profile_id_fkindex on catalog_master  (cost=0.00..4.19
> rows=1 width=446) (actual time=0.008..0.008 rows=0 loops=1160)
>                                  Index Cond:
> (catalog_master.profile_id = b.profile_id)
>                                  Filter: ((catalog_master.hide IS
> FALSE) AND ((catalog_master.hosting_status)::text = 'ACTIVE'::text))
>                      ->  Index Scan using
> profile_master_profile_id_pkey on profile_master  (cost=0.00..7.11
> rows=1 width=9) (actual time=0.012..0.012 rows=1 loops=25)
>                            Index Cond: (profile_master.profile_id =
> catalog_master.profile_id)
>                ->  Index Scan using
> catalog_categories_pkey_catalog_id_category_id on catalog_categories
> (cost=0.00..0.56 rows=1 width=8) (actual time=0.010..0.011 rows=1
> loops=25)
>                      Index Cond: (catalog_categories.catalog_id =
> catalog_master.catalog_id)
>                      Filter: (catalog_categories.ifmain IS TRUE)
>          ->  Index Scan using web_category_master_pkey on
> web_category_master  (cost=0.00..0.90 rows=1 width=4) (actual
> time=0.009..0.010 rows=1 loops=25)
>                Index Cond: (web_category_master.category_id =
> catalog_categories.category_id)
>                Filter: ((web_category_master.status)::text =
> 'ACTIVE'::text)
>  Total runtime: 63.378 ms
>
>

On Monday 28 June 2010 13:39:27 Yeb Havinga wrote:
> It looks like seq_scans are disabled, since the index scan has only a
> filter expression but not an index cond.
Or its using it to get an ordered result...

Andres

Rajesh Kumar Mallah <mallah.rajesh@gmail.com> wrote:

> just by removing the order by co_name reduces the query time
> dramatically from  ~ 9 sec  to 63 ms. Can anyone please help.

The reason is that one query allows it to return *any* 25 rows,
while the other query requires it to find a *specific* set of 25
rows.  It happens to be faster to just grab any old set of rows than
to find particular ones.

If the actual results you need are the ones sorted by name, then
forget the other query and focus on how you can retrieve the desired
results more quickly.  One valuable piece of information would be to
know how many rows the query would return without the limit.  It's
also possible that your costing factors may need adjustment.  Or you
may need to get finer-grained statistics -- the optimizer thought it
would save time to use an index in the sequence you wanted, but it
had to scan through 2212 rows to find 25 rows which matched the
selection criteria.  It might well have been faster to use a table
scan and sort than to follow the index like that.

-Kevin

"Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes:
> Rajesh Kumar Mallah <mallah.rajesh@gmail.com> wrote:
>> just by removing the order by co_name reduces the query time
>> dramatically from  ~ 9 sec  to 63 ms. Can anyone please help.

> The reason is that one query allows it to return *any* 25 rows,
> while the other query requires it to find a *specific* set of 25
> rows.  It happens to be faster to just grab any old set of rows than
> to find particular ones.

I'm guessing that most of the cost is in repeated evaluations of the
filter clause
    (co_name_vec)::tsvector @@ to_tsquery('manufacturer'::text)

There are two extremely expensive functions involved there (cast to
tsvector and to_tsquery) and they're being done over again at what
I suspect is practically every table row.  The unordered query is
so much faster because it stops after having evaluated the text
search clause just a few times.

The way to make this go faster is to set up the actually recommended
infrastructure for full text search, namely create an index on
(co_name_vec)::tsvector (either directly or using an auxiliary tsvector
column).  If you don't want to maintain such an index, fine, but don't
expect full text search queries to be quick.

            regards, tom lane

Rajesh Kumar Mallah <mallah.rajesh@gmail.com> writes:
> co_name_vec is actually the auxiliary tsvector column that is mantained via
> a
> an update trigger. and the index that you suggested is there .

Well, in that case it's just a costing/statistics issue.  The planner is
probably estimating there are more tsvector matches than there really
are, which causes it to think the in-order indexscan will terminate
earlier than it really will, so it goes for that instead of a full scan
and sort.  If this is 8.4 then increasing the statistics target for the
co_name_vec column should help that.  In previous versions I'm not sure
how much you can do about it other than raise random_page_cost, which is
likely to be a net loss overall.

            regards, tom lane