Thread: order by slowing down a query by 80 times

order by slowing down a query by 80 times

From
Rajesh Kumar Mallah
Date:
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.

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



Re: order by slowing down a query by 80 times

From
Yeb Havinga
Date:
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
>
>


Re: order by slowing down a query by 80 times

From
Andres Freund
Date:
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

Re: order by slowing down a query by 80 times

From
Rajesh Kumar Mallah
Date:


On Mon, Jun 28, 2010 at 5:09 PM, Yeb Havinga <yebhavinga@gmail.com> wrote:
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.


seq_scans is NOT explicitly disabled. The two queries just differed in the order by clause.

regds
Rajesh Kumar Mallah.
 

regards,
Yeb Havinga



Regds
Rajesh Kumar Mallah.

Re: order by slowing down a query by 80 times

From
"Kevin Grittner"
Date:
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

Re: order by slowing down a query by 80 times

From
Tom Lane
Date:
"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

Re: order by slowing down a query by 80 times

From
Rajesh Kumar Mallah
Date:
Dear Tom/Kevin/List

thanks for the insight, i will check the suggestion more closely and post
the results.

regds
Rajesh Kumar Mallah.
 
#avg_ls_inline_popup { position:absolute; z-index:9999; padding: 0px 0px; margin-left: 0px; margin-top: 0px; width: 240px; overflow: hidden; word-wrap: break-word; color: black; font-size: 10px; text-align: left; line-height: 13px;}

Re: order by slowing down a query by 80 times

From
Rajesh Kumar Mallah
Date:



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
 


Dear Tom/List ,

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 . consider simplified
version. When we  order by co_name the index on co_name_vec is not used
some other index is used.

 tradein_clients=> explain analyze SELECT  profile_id from  general.profile_master b  where  1=1  and co_name_vec @@   to_tsquery ('manufacturer')   order by co_name  limit 25;
                                                                        QUERY PLAN                                                        
-----------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=0.00..3958.48 rows=25 width=25) (actual time=0.045..19.847 rows=25 loops=1)
   ->  Index Scan using profile_master_co_name on profile_master b  (cost=0.00..1125315.59 rows=7107 width=25) (actual time=0.043..19.818 rows=25 loops=1)
         Filter: ((co_name_vec)::tsvector @@ to_tsquery('manufacturer'::text))
 Total runtime: 19.894 ms
(4 rows)

tradein_clients=> explain analyze SELECT  profile_id from  general.profile_master b  where  1=1  and co_name_vec @@   to_tsquery ('manufacturer')    limit 25;
                                                                        QUERY PLAN                                                        
-----------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=0.00..101.18 rows=25 width=4) (actual time=0.051..0.632 rows=25 loops=1)
   ->  Index Scan using profile_master_co_name_vec on profile_master b  (cost=0.00..28761.89 rows=7107 width=4) (actual time=0.049..0.593 rows=25 loops=1)
         Index Cond: ((co_name_vec)::tsvector @@ to_tsquery('manufacturer'::text))
 Total runtime: 0.666 ms
(4 rows)

tradein_clients=>         

 

#avg_ls_inline_popup { position:absolute; z-index:9999; padding: 0px 0px; margin-left: 0px; margin-top: 0px; width: 240px; overflow: hidden; word-wrap: break-word; color: black; font-size: 10px; text-align: left; line-height: 13px;}

Re: order by slowing down a query by 80 times

From
Tom Lane
Date:
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