Re: order by slowing down a query by 80 times

From: Yeb Havinga <yebhavinga(at)gmail(dot)com>
To: Rajesh Kumar Mallah <mallah(dot)rajesh(at)gmail(dot)com>
Cc: pgsql-performance(at)postgresql(dot)org
Subject: Re: order by slowing down a query by 80 times
Date: 2010-06-28 11:39:27
Message-ID: 4C2889EF.1050908@gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-performance

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
>
>

In response to

Responses

Browse pgsql-performance by date

  From Date Subject
Next Message Andres Freund 2010-06-28 13:26:34 Re: order by slowing down a query by 80 times
Previous Message Rajesh Kumar Mallah 2010-06-28 11:08:41 order by slowing down a query by 80 times