Thread: Slow Query

Slow Query

From

Marc McIntyre

Date:

14 July 2005, 00:07:58

Hi,

I'm having a problem with a query that performs a sequential scan on a
table when it should be performing an index scan. The interesting thing
is, when we dumped the database on another server, it performed an index
scan on that server. The systems are running the same versions of
postgres (7.4.8) and the problem persists after running an "ANALYZE
VERBOSE" and after a "REINDEX TABLE sq_ast FORCE". The only difference
that i can see is that the postgresql.conf files differ slightly, and
the hardware is different. Note that the system performing the
sequential scan is a Dual 2.8GHz Xeon, 4GB Ram, 300GB HDD. And the
system performing an index scan is not as powerful.

A copy of the postgresql.conf for the system performing the index scan
can be found at http://beta.squiz.net/~mmcintyre/postgresql_squiz_uk.conf
A copy of the postgresql.conf for the system performing the sequential
scan can be found at http://beta.squiz.net/~mmcintyre/postgresql_future.conf

The Query:

SELECT a.assetid, a.short_name, a.type_code, a.status, l.linkid,
l.link_type, l.sort_order, lt.num_kids, u.url, ap.path,
     CASE u.http
                WHEN '1' THEN 'http'
                WHEN '0' THEN 'https'
     END AS protocol
FROM ((sq_ast a LEFT JOIN sq_ast_url u ON a.assetid = u.assetid) LEFT
JOIN sq_ast_path ap ON a.assetid = ap.assetid),sq_ast_lnk l,
sq_ast_lnk_tree lt WHERE a.assetid = l.minorid AND
          l.linkid = lt.linkid AND l.majorid = '2' AND
          l.link_type <= 2 ORDER BY sort_order


The EXPLAIN ANALYZE from the system performing an sequential scan:

QUERY PLAN
Sort  (cost=30079.79..30079.89 rows=42 width=113) (actual time=39889.989..39890.346 rows=260 loops=1)
  Sort Key: l.sort_order
  ->  Nested Loop  (cost=25638.02..30078.65 rows=42 width=113) (actual time=9056.336..39888.557 rows=260 loops=1)
        ->  Merge Join  (cost=25638.02..29736.01 rows=25 width=109) (actual time=9056.246..39389.359 rows=260 loops=1)
              Merge Cond: (("outer".assetid)::text = "inner"."?column5?")
              ->  Merge Left Join  (cost=25410.50..29132.82 rows=150816 width=97) (actual time=8378.176..38742.111
rows=150567loops=1) 
                    Merge Cond: (("outer".assetid)::text = ("inner".assetid)::text)
                    ->  Merge Left Join  (cost=25410.50..26165.14 rows=150816 width=83) (actual time=8378.130..9656.413
rows=150489loops=1) 
                          Merge Cond: ("outer"."?column5?" = "inner"."?column4?")
                          ->  Sort  (cost=25408.17..25785.21 rows=150816 width=48) (actual time=8377.733..8609.218
rows=150486loops=1) 
                                Sort Key: (a.assetid)::text
                                ->  Seq Scan on sq_ast a  (cost=0.00..12436.16 rows=150816 width=48) (actual
time=0.011..5578.231rows=151378 loops=1) 
                          ->  Sort  (cost=2.33..2.43 rows=37 width=43) (actual time=0.364..0.428 rows=37 loops=1)
                                Sort Key: (u.assetid)::text
                                ->  Seq Scan on sq_ast_url u  (cost=0.00..1.37 rows=37 width=43) (actual
time=0.023..0.161rows=37 loops=1) 
                    ->  Index Scan using sq_ast_path_ast on sq_ast_path ap  (cost=0.00..2016.98 rows=45893 width=23)
(actualtime=0.024..14041.571 rows=45812 loops=1) 
              ->  Sort  (cost=227.52..227.58 rows=25 width=21) (actual time=131.838..132.314 rows=260 loops=1)
                    Sort Key: (l.minorid)::text
                    ->  Index Scan using sq_ast_lnk_majorid on sq_ast_lnk l  (cost=0.00..226.94 rows=25 width=21)
(actualtime=0.169..126.201 rows=260 loops=1) 
                          Index Cond: ((majorid)::text = '2'::text)
                          Filter: (link_type <= 2)
        ->  Index Scan using sq_ast_lnk_tree_linkid on sq_ast_lnk_tree lt  (cost=0.00..13.66 rows=3 width=8) (actual
time=1.539..1.900rows=1 loops=260) 
              Index Cond: ("outer".linkid = lt.linkid)
Total runtime: 39930.395 ms


The EXPLAIN ANALYZE from the system performing an index scan scan:


Sort  (cost=16873.64..16873.74 rows=40 width=113) (actual time=2169.905..2169.912 rows=13 loops=1)
   Sort Key: l.sort_order
   ->  Nested Loop  (cost=251.39..16872.58 rows=40 width=113) (actual time=45.724..2169.780 rows=13 loops=1)
         ->  Merge Join  (cost=251.39..16506.42 rows=32 width=109) (actual time=45.561..2169.012 rows=13 loops=1)
               Merge Cond: (("outer".assetid)::text = "inner"."?column5?")
               ->  Merge Left Join  (cost=2.33..15881.92 rows=149982 width=97) (actual time=0.530..1948.718 rows=138569
loops=1)
                     Merge Cond: (("outer".assetid)::text = ("inner".assetid)::text)
                     ->  Merge Left Join  (cost=2.33..13056.04 rows=149982 width=83) (actual time=0.406..953.781
rows=138491loops=1) 
                           Merge Cond: (("outer".assetid)::text = "inner"."?column4?")
                           ->  Index Scan using sq_ast_pkey on sq_ast a  (cost=0.00..14952.78 rows=149982 width=48)
(actualtime=0.154..388.872 rows=138488 loops=1) 
                           ->  Sort  (cost=2.33..2.43 rows=37 width=43) (actual time=0.235..0.264 rows=37 loops=1)
                                 Sort Key: (u.assetid)::text
                                 ->  Seq Scan on sq_ast_url u  (cost=0.00..1.37 rows=37 width=43) (actual
time=0.036..0.103rows=37 loops=1) 
                     ->  Index Scan using sq_ast_path_ast on sq_ast_path ap  (cost=0.00..1926.18 rows=42071 width=23)
(actualtime=0.110..105.918 rows=42661 loops=1) 
               ->  Sort  (cost=249.05..249.14 rows=36 width=21) (actual time=0.310..0.324 rows=13 loops=1)
                     Sort Key: (l.minorid)::text
                     ->  Index Scan using sq_ast_lnk_majorid on sq_ast_lnk l  (cost=0.00..248.12 rows=36 width=21)
(actualtime=0.141..0.282 rows=13 loops=1) 
                           Index Cond: ((majorid)::text = '2'::text)
                           Filter: (link_type <= 2)
         ->  Index Scan using sq_ast_lnk_tree_linkid on sq_ast_lnk_tree lt  (cost=0.00..11.41 rows=2 width=8) (actual
time=0.043..0.045rows=1 loops=13) 
               Index Cond: ("outer".linkid = lt.linkid)
 Total runtime: 2170.165 ms
(22 rows)

THE DESC of the sq_ast table.


future_v3_schema=# \d sq_ast

                                       Table "public.sq_ast"
        Column | Type | Modifiers
-----------------------+-----------------------------+---------------------------------------------
 assetid | character varying(15) | not null
 type_code | character varying(100) | not null
 version | character varying(20) | not null default '0.0.0'::character
varying
 name | character varying(255) | not null default ''::character varying
 short_name | character varying(255) | not null default ''::character
varying
 status | integer | not null default 1
 languages | character varying(50) | not null default ''::character varying
 charset | character varying(50) | not null default ''::character varying
 force_secure | character(1) | not null default '0'::bpchar
 created | timestamp without time zone | not null
 created_userid | character varying(255) | not null
 updated | timestamp without time zone | not null
 updated_userid | character varying(255) | not null
 published | timestamp without time zone |
 published_userid | character varying(255) |
 status_changed | timestamp without time zone |
 status_changed_userid | character varying(255) |
Indexes:
    "sq_asset_pkey" primary key, btree (assetid)
    "sq_ast_created" btree (created)
    "sq_ast_name" btree (name)
    "sq_ast_published" btree (published)
    "sq_ast_type_code" btree (type_code)
    "sq_ast_updated" btree (updated)


Any ideas?

--
Marc McIntyre
MySource Matrix Lead Developer

Re: Slow Query

From

Ragnar Hafstað

Date:

14 July 2005, 11:20:59

On Thu, 2005-07-14 at 10:06 +1000, Marc McIntyre wrote:

> I'm having a problem with a query that performs a sequential scan on a
> table when it should be performing an index scan. The interesting thing
> is, when we dumped the database on another server, it performed an index
> scan on that server.
...
> The EXPLAIN ANALYZE from the system performing an sequential scan:
>
> QUERY PLAN
> Sort  (cost=30079.79..30079.89 rows=42 width=113) (actual time=39889.989..39890.346 rows=260 loops=1)
...
> The EXPLAIN ANALYZE from the system performing an index scan scan:
> Sort  (cost=16873.64..16873.74 rows=40 width=113) (actual time=2169.905..2169.912 rows=13 loops=1)

looks like the first query is returning 260 rows,
but the second one 13

this may not be your problem, but are you sure you are using the same
query on the same data here ?

gnari

Re: Slow Query

From

Joe Lester

Date:

21 November 2006, 19:28:49

Pretty sure. When I ran the queries I was in psql. I ran the first
query. Then I pressed the up arrow to re-run the same query. I did
not notice that about the rows. Might reindexing be in order?

On Jul 14, 2005, at 7:22 AM, Ragnar Hafstað wrote:

> On Thu, 2005-07-14 at 10:06 +1000, Marc McIntyre wrote:
>
>> I'm having a problem with a query that performs a sequential scan
>> on a
>> table when it should be performing an index scan. The interesting
>> thing
>> is, when we dumped the database on another server, it performed an
>> index
>> scan on that server.
> ...
>> The EXPLAIN ANALYZE from the system performing an sequential scan:
>>
>> QUERY PLAN
>> Sort  (cost=30079.79..30079.89 rows=42 width=113) (actual
>> time=39889.989..39890.346 rows=260 loops=1)
> ...
>> The EXPLAIN ANALYZE from the system performing an index scan scan:
>> Sort  (cost=16873.64..16873.74 rows=40 width=113) (actual
>> time=2169.905..2169.912 rows=13 loops=1)
>
> looks like the first query is returning 260 rows,
> but the second one 13
>
> this may not be your problem, but are you sure you are using the same
> query on the same data here ?
>
> gnari
>
>
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 2: Don't 'kill -9' the postmaster
>
>