Re: 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(at)denninger(dot)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
>
>