Message-ID: <42D5AC8A.9000003@squiz.net>
Date: Thu, 14 Jul 2005 10:06:34 +1000
From: Marc McIntyre <mmcintyre@squiz.net>
User-Agent: Mozilla Thunderbird 1.0.2 (Windows/20050317)
MIME-Version: 1.0
To: pgsql-performance@postgresql.org
Subject: Slow Query
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit

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=150567 loops=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=150489 loops=1)
                          Merge Cond: ("outer"."?column5?" = "inner"."?column4?")
                          ->  Sort  (cost=25408.17..25785.21 rows=150816 width=48) (actual time=8377.733..8609.218 rows=150486 loops=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.231 rows=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.161 rows=37 loops=1)
                    ->  Index Scan using sq_ast_path_ast on sq_ast_path ap  (cost=0.00..2016.98 rows=45893 width=23) (actual time=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) (actual time=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.900 rows=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=138491 loops=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) (actual time=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.103 rows=37 loops=1)
                     ->  Index Scan using sq_ast_path_ast on sq_ast_path ap  (cost=0.00..1926.18 rows=42071 width=23) (actual time=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) (actual time=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.045 rows=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