Re: [PERFORM] SQL Query Performance - what gives?

First query:


ticker=# explain analyze select * from post, forum where forum.name = post.forum and invisible <> 1 and to_tsvector('english', message) @@ to_tsquery('violence') order by modified desc limit 100;
                                                                   QUERY PLAN                                                                  
------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=5959.78..5960.03 rows=100 width=706) (actual time=49.847..50.264 rows=100 loops=1)
   ->  Sort  (cost=5959.78..5963.30 rows=1408 width=706) (actual time=49.843..49.982 rows=100 loops=1)
         Sort Key: post.modified
         Sort Method:  top-N heapsort  Memory: 168kB
         ->  Hash Join  (cost=621.72..5905.96 rows=1408 width=706) (actual time=4.050..41.238 rows=2055 loops=1)
               Hash Cond: (post.forum = forum.name)
               ->  Bitmap Heap Scan on post  (cost=370.93..5635.71 rows=1435 width=435) (actual time=3.409..32.648 rows=2055 loops=1)
                     Recheck Cond: (to_tsvector('english'::text, message) @@ to_tsquery('violence'::text))
                     Filter: (invisible <> 1)
                     ->  Bitmap Index Scan on idx_message  (cost=0.00..370.57 rows=1435 width=0) (actual time=2.984..2.984 rows=2085 loops=1)
                           Index Cond: (to_tsvector('english'::text, message) @@ to_tsquery('violence'::text))
               ->  Hash  (cost=249.97..249.97 rows=66 width=271) (actual time=0.596..0.596 rows=64 loops=1)
                     ->  Index Scan using forum_name on forum  (cost=0.00..249.97 rows=66 width=271) (actual time=0.093..0.441 rows=64 loops=1)
 Total runtime: 50.625 ms
(14 rows)

ticker=#

Second query:



ticker=# explain analyze select * from post, forum where forum.name = post.forum and invisible <> 1 and ((permission & '127') = permission) and (contrib is null or contrib = ' ' or contrib like '%b%') and  to_tsvector('english', message) @@ to_tsquery('violence') order by modified desc limit 100;
                                                                       QUERY PLAN                                                                      
--------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=1337.71..1337.76 rows=21 width=706) (actual time=31121.317..31121.736 rows=100 loops=1)
   ->  Sort  (cost=1337.71..1337.76 rows=21 width=706) (actual time=31121.313..31121.452 rows=100 loops=1)
         Sort Key: post.modified
         Sort Method:  top-N heapsort  Memory: 168kB
         ->  Nested Loop  (cost=978.97..1337.25 rows=21 width=706) (actual time=2.841..31108.926 rows=2055 loops=1)
               ->  Index Scan using forum_name on forum  (cost=0.00..250.63 rows=1 width=271) (actual time=0.013..0.408 rows=63 loops=1)
                     Filter: (((contrib IS NULL) OR (contrib = ' '::text) OR (contrib ~~ '%b%'::text)) AND ((permission & 127) = permission))
               ->  Bitmap Heap Scan on post  (cost=978.97..1086.28 rows=27 width=435) (actual time=109.832..493.648 rows=33 loops=63)
                     Recheck Cond: ((to_tsvector('english'::text, post.message) @@ to_tsquery('violence'::text)) AND (post.forum = forum.name))
                     Filter: (post.invisible <> 1)
                     ->  BitmapAnd  (cost=978.97..978.97 rows=27 width=0) (actual time=98.832..98.832 rows=0 loops=63)
                           ->  Bitmap Index Scan on idx_message  (cost=0.00..370.57 rows=1435 width=0) (actual time=0.682..0.682 rows=2085 loops=63)
                                 Index Cond: (to_tsvector('english'::text, post.message) @@ to_tsquery('violence'::text))
                           ->  Bitmap Index Scan on post_forum  (cost=0.00..607.78 rows=26575 width=0) (actual time=97.625..97.625 rows=22616 loops=63)
                                 Index Cond: (post.forum = forum.name)
 Total runtime: 31122.781 ms
(16 rows)

ticker=#
ticker=# \d post
                                      Table "public.post"
  Column   |           Type           |                       Modifiers                       
-----------+--------------------------+--------------------------------------------------------
 forum     | text                     |
 number    | integer                  |
 toppost   | integer                  |
 views     | integer                  | default 0
 login     | text                     |
 subject   | text                     |
 message   | text                     |
 inserted  | timestamp with time zone |
 modified  | timestamp with time zone |
 replied   | timestamp with time zone |
 who       | text                     |
 reason    | text                     |
 ordinal   | integer                  | not null default nextval('post_ordinal_seq'::regclass)
 replies   | integer                  | default 0
 invisible | integer                  |
 sticky    | integer                  |
 ip        | inet                     |
 lock      | integer                  | default 0
 pinned    | integer                  | default 0
 marked    | boolean                  |
Indexes:
    "post_pkey" PRIMARY KEY, btree (ordinal)
    "idx_message" gin (to_tsvector('english'::text, message))
    "idx_subject" gin (to_tsvector('english'::text, subject))
    "post_forum" btree (forum)
    "post_getlastpost" btree (forum, modified)
    "post_inserted" btree (inserted)
    "post_login" btree (login)
    "post_modified" btree (modified)
    "post_number" btree (number)
    "post_order" btree (number, inserted)
    "post_ordinal" btree (ordinal)
    "post_top" btree (toppost)
    "post_toppost" btree (forum, toppost, inserted)
Foreign-key constraints:
    "forum_fk" FOREIGN KEY (forum) REFERENCES forum(name) ON UPDATE CASCADE ON DELETE CASCADE
    "login_fk" FOREIGN KEY (login) REFERENCES usertable(login) ON UPDATE CASCADE ON DELETE CASCADE
Triggers:
    _tickerforum_logtrigger AFTER INSERT OR DELETE OR UPDATE ON post FOR EACH ROW EXECUTE PROCEDURE _tickerforum.logtrigger('_tickerforum', '20', 'vvvvvvvvvvvvk')
Disabled triggers:
    _tickerforum_denyaccess BEFORE INSERT OR DELETE OR UPDATE ON post FOR EACH ROW EXECUTE PROCEDURE _tickerforum.denyaccess('_tickerforum')

ticker=# \d forum
                Table "public.forum"
   Column    |           Type           | Modifiers
-------------+--------------------------+-----------
 name        | text                     | not null
 description | text                     |
 long_desc   | text                     |
 forum_type  | integer                  |
 forum_order | integer                  |
 lastpost    | timestamp with time zone |
 lastperson  | text                     |
 permission  | integer                  | default 0
 modtime     | integer                  |
 numposts    | integer                  | default 0
 type        | integer                  | default 0
 readonly    | integer                  | default 0
 moderated   | integer                  | default 0
 flags       | integer                  |
 rsslength   | text                     |
 contrib     | text                     |
 autolock    | text                     |
 autodest    | text                     |
 open        | text                     |
Indexes:
    "forum_pkey" PRIMARY KEY, btree (name)
    "forum_name" UNIQUE, btree (name)
    "forum_order" UNIQUE, btree (forum_order)
Triggers:
    _tickerforum_logtrigger AFTER INSERT OR DELETE OR UPDATE ON forum FOR EACH ROW EXECUTE PROCEDURE _tickerforum.logtrigger('_tickerforum', '7', 'k')
Disabled triggers:
    _tickerforum_denyaccess BEFORE INSERT OR DELETE OR UPDATE ON forum FOR EACH ROW EXECUTE PROCEDURE _tickerforum.denyaccess('_tickerforum')

(The triggers exist due to replication via Slony)


Kevin Grittner wrote:

Karl Denninger <karl@denninger.net> wrote: 

Let's take the following EXPLAIN results:   

 
We could tell a lot more from EXPLAIN ANALYZE results.
The table definitions (with index information) would help, too.
-Kevin