Message-ID: <4A8B04C7.6060702@denninger.net>
Date: Tue, 18 Aug 2009 14:45:11 -0500
From: Karl Denninger <karl@denninger.net>
User-Agent: Thunderbird 2.0.0.22 (Windows/20090605)
MIME-Version: 1.0
To: pgsql-sql@postgresql.org, pgsql-performance@postgresql.org
Subject: SQL Query Performance - what gives?
Content-Type: multipart/mixed; boundary="------------060708040808070501050806"

This is a multi-part message in MIME format.
--------------060708040808070501050806
Content-Type: text/plain; charset=ISO-8859-1
Content-Transfer-Encoding: 7bit


Let's take the following EXPLAIN results:

ticker=# explain 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=5951.85..5952.10 rows=100 width=706)
   ->  Sort  (cost=5951.85..5955.37 rows=1408 width=706)
         Sort Key: post.modified
         ->  Hash Join  (cost=613.80..5898.04 rows=1408 width=706)
               Hash Cond: (post.forum = forum.name)
               ->  Bitmap Heap Scan on post  (cost=370.93..5635.71
rows=1435 width=435)
                     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)
                           Index Cond: (to_tsvector('english'::text,
message) @@ to_tsquery('violence'::text))
               ->  Hash  (cost=242.07..242.07 rows=64 width=271)
                     ->  Index Scan using forum_name on forum 
(cost=0.00..242.07 rows=64 width=271)
(12 rows)

ticker=#

And


ticker=# explain 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=1329.81..1329.87 rows=22 width=706)
   ->  Sort  (cost=1329.81..1329.87 rows=22 width=706)
         Sort Key: post.modified
         ->  Nested Loop  (cost=978.96..1329.32 rows=22 width=706)
               ->  Index Scan using forum_name on forum 
(cost=0.00..242.71 rows=1 width=271)
                     Filter: (((contrib IS NULL) OR (contrib = '
'::text) OR (contrib ~~ '%b%'::text)) AND ((permission & 127) = permission))
               ->  Bitmap Heap Scan on post  (cost=978.96..1086.28
rows=27 width=435)
                     Recheck Cond: ((to_tsvector('english'::text,
post.message) @@ to_tsquery('violence'::text)) AND (post.forum =
forum.name))
                     Filter: (post.invisible <> 1)
                     ->  BitmapAnd  (cost=978.96..978.96 rows=27 width=0)
                           ->  Bitmap Index Scan on idx_message 
(cost=0.00..370.57 rows=1435 width=0)
                                 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)
                                 Index Cond: (post.forum = forum.name)
(14 rows)

ticker=#


The difference in these two queries is that the second qualifies the
returned search to check two permission blocks - one related to the
user's permission bit mask, and the second a mask of single-character
"flags" (the user's classification must be in the list of permitted
classifications)

Ok.  Notice that the top-line cost of the first query is HIGHER.

The first query runs almost instantly - average execution latency is
frequently in the few-hundred millisecond range.

The second query can take upward of 30 seconds (!) to run.

Neither hits the disk, the machine in question has scads of free RAM
available, and while busy is not particularly constrained.  Other
simultaneous users on the database are getting queries back immediately
(no unreasonable delays).

If I remove parts of the permission tests it does not matter.  If ANY of
those tests qualifies the returned values the performance goes in the
toilet.  If I re-order when the permission tests appear (e.g. at the end
of the search command) it makes no difference in the response time
either (it does, however, change the EXPLAIN output somewhat, and
thereby appears to change the query plan.

What's going on here?  I can usually figure out what's causing bad
performance and fix it with the judicious addition of an index or other
similar thing - this one has me completely mystified.

-- Karl

--------------060708040808070501050806
Content-Type: text/x-vcard; charset=utf-8;
 name="karl.vcf"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
 filename="karl.vcf"

begin:vcard
fn:Karl Denninger
n:Denninger;Karl
org:Cuda Systems LLC
adr;dom:;;314 Olde Post Road;Niceville;FL;32578
email;internet:karl@denninger.net
tel;work:850-376-9364
tel;fax:850-897-9364
x-mozilla-html:TRUE
url:http://market-ticker.org
version:2.1
end:vcard


--------------060708040808070501050806--