Received: from localhost (unknown [200.46.208.211]) by mail.postgresql.org (Postfix) with ESMTP id 8A435633C9F for ; Tue, 18 Aug 2009 20:04:59 -0300 (ADT) Received: from mail.postgresql.org ([200.46.204.86]) by localhost (mx1.hub.org [200.46.208.211]) (amavisd-maia, port 10024) with ESMTP id 97695-05 for ; Tue, 18 Aug 2009 23:04:42 +0000 (UTC) X-Greylist: from auto-whitelisted by SQLgrey-1.7.6 Received: from FS.denninger.net (wsip-70-169-168-7.pn.at.cox.net [70.169.168.7]) by mail.postgresql.org (Postfix) with ESMTP id 03CDF63370C for ; Tue, 18 Aug 2009 20:04:47 -0300 (ADT) Received: from [127.0.0.1] (localhost [127.0.0.1]) by FS.denninger.net (8.14.3/8.13.1) with SMTP id n7IN4ki0062712 for ; Tue, 18 Aug 2009 18:04:47 -0500 (CDT) (envelope-from karl@denninger.net) Received: from [127.0.0.1] [192.168.1.40] by Spamblock-sys (LOCAL); Tue Aug 18 18:04:47 2009 Message-ID: <4A8B334F.1010801@denninger.net> Date: Tue, 18 Aug 2009 18:03:44 -0500 From: Karl Denninger User-Agent: Thunderbird 2.0.0.22 (Windows/20090605) MIME-Version: 1.0 To: Kevin Grittner CC: pgsql-performance@postgresql.org, pgsql-sql@postgresql.org Subject: Re: SQL Query Performance - what gives? References: <4A8B04C7.6060702@denninger.net> <4A8AC75C0200002500029C8A@gw.wicourts.gov> <4A8B1606.2040209@denninger.net> <4A8ADDEA0200002500029CA3@gw.wicourts.gov> In-Reply-To: <4A8ADDEA0200002500029CA3@gw.wicourts.gov> X-Enigmail-Version: 0.96.0 Content-Type: multipart/mixed; boundary="------------060703030907070804000005" X-Antivirus: avast! (VPS 090818-0, 08/18/2009), Outbound message X-Antivirus-Status: Clean X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=-2.498 tagged_above=-10 required=5 tests=AWL=-0.000, BAYES_00=-2.599, HTML_MESSAGE=0.001, RDNS_DYNAMIC=0.1 X-Spam-Level: X-Archive-Number: 200908/201 X-Sequence-Number: 35233 This is a multi-part message in MIME format. --------------060703030907070804000005 Content-Type: multipart/alternative; boundary="------------050103040001030800070503" --------------050103040001030800070503 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Kevin Grittner wrote: > Karl Denninger wrote: > >> -> 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)) >> > > The biggest issue, as far as I can see, is that it thinks that the > selection criteria on forum will limit to one row, while it really > matches 63 rows. > > You might be able to coerce it into a faster plan with something like > this (untested): > > select * > from (select * from post > where invisible <> 1 > and to_tsvector('english', message) > @@ to_tsquery('violence') > ) p, > forum > where forum.name = p.forum > and (permission & '127') = permission > and (contrib is null or contrib = ' ' or contrib like '%b%') > order by modified desc > limit 100 > ; > > -Kevin > That didn't help. The FTS alone returns 2,000 records on that table, and does so VERY quickly: ticker=# explain analyze select count(ordinal) from post, forum where post.forum=forum.name and invisible <> 1 and to_tsvector('english', message) @@ to_tsquery('violence'); QUERY PLAN ---------------------------------------------------------------------------------------------------------------------------------------- Aggregate (cost=5901.57..5901.58 rows=1 width=4) (actual time=17.492..17.494 rows=1 loops=1) -> Hash Join (cost=613.80..5898.04 rows=1408 width=4) (actual time=1.436..14.620 rows=2056 loops=1) Hash Cond: (post.forum = forum.name) -> Bitmap Heap Scan on post (cost=370.93..5635.71 rows=1435 width=14) (actual time=1.123..7.944 rows=2056 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=0.738..0.738 rows=2099 loops=1) Index Cond: (to_tsvector('english'::text, message) @@ to_tsquery('violence'::text)) -> Hash (cost=242.07..242.07 rows=64 width=9) (actual time=0.300..0.300 rows=64 loops=1) -> Index Scan using forum_name on forum (cost=0.00..242.07 rows=64 width=9) (actual time=0.011..0.182 rows=64 loops=1) Total runtime: 17.559 ms (11 rows) ticker=# Ok, but now when we check the permission mask.... ticker=# explain analyze select count(ordinal) from post, forum where post.forum=forum.name and invisible <> 1 and to_tsvector('english', message) @@ to_tsquery('violence') and (permission & 4 = permission); QUERY PLAN -------------------------------------------------------------------------------------------------------------------------------------------------- Aggregate (cost=1329.07..1329.08 rows=1 width=4) (actual time=29819.293..29819.295 rows=1 loops=1) -> Nested Loop (cost=978.97..1329.01 rows=22 width=4) (actual time=2.575..29815.530 rows=2056 loops=1) -> Index Scan using forum_name on forum (cost=0.00..242.39 rows=1 width=13) (actual time=0.016..0.355 rows=62 loops=1) Filter: ((permission & 4) = permission) -> Bitmap Heap Scan on post (cost=978.97..1086.28 rows=27 width=14) (actual time=97.997..480.746 rows=33 loops=62) 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=91.106..91.106 rows=0 loops=62) -> Bitmap Index Scan on idx_message (cost=0.00..370.57 rows=1435 width=0) (actual time=0.680..0.680 rows=2099 loops=62) 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=89.927..89.927 rows=22980 loops=62) Index Cond: (post.forum = forum.name) Total runtime: 29819.376 ms (13 rows) ticker=# The problem appearsa to lie in the "nested loop", and I don't understand why that's happening. Isn't a **LINEAR** check on each returned value (since we do the aggregate first?) sufficient? Why is the query planner creating a nested loop - the aggregate contains the tested field and it is not subject to change once aggregated?! --------------050103040001030800070503 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Kevin Grittner wrote: 
Karl Denninger <karl@denninger.net> wrote:
  
               ->  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))
    
 
The biggest issue, as far as I can see, is that it thinks that the
selection criteria on forum will limit to one row, while it really
matches 63 rows.
 
You might be able to coerce it into a faster plan with something like
this (untested):
 
select *
  from (select * from post
          where invisible <> 1
            and to_tsvector('english', message)
             @@ to_tsquery('violence')
       ) p,
  forum
  where forum.name = p.forum
    and (permission & '127') = permission
    and (contrib is null or contrib = ' ' or contrib like '%b%')
  order by modified desc
  limit 100
;
 
-Kevin

That didn't help.

The FTS alone returns 2,000 records on that table, and does so VERY quickly:

ticker=# explain analyze select count(ordinal) from post, forum where post.forum=forum.name and invisible <> 1
            and to_tsvector('english', message)
             @@ to_tsquery('violence');
                                                               QUERY PLAN                                                              
----------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=5901.57..5901.58 rows=1 width=4) (actual time=17.492..17.494 rows=1 loops=1)
   ->  Hash Join  (cost=613.80..5898.04 rows=1408 width=4) (actual time=1.436..14.620 rows=2056 loops=1)
         Hash Cond: (post.forum = forum.name)
         ->  Bitmap Heap Scan on post  (cost=370.93..5635.71 rows=1435 width=14) (actual time=1.123..7.944 rows=2056 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=0.738..0.738 rows=2099 loops=1)
                     Index Cond: (to_tsvector('english'::text, message) @@ to_tsquery('violence'::text))
         ->  Hash  (cost=242.07..242.07 rows=64 width=9) (actual time=0.300..0.300 rows=64 loops=1)
               ->  Index Scan using forum_name on forum  (cost=0.00..242.07 rows=64 width=9) (actual time=0.011..0.182 rows=64 loops=1)
 Total runtime: 17.559 ms
(11 rows)

ticker=#

Ok, but now when we check the permission mask....


ticker=# explain analyze select count(ordinal) from post, forum where post.forum=forum.name and invisible <> 1
            and to_tsvector('english', message)
             @@ to_tsquery('violence') and (permission & 4 = permission);
                                                                    QUERY PLAN                                                                   
--------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=1329.07..1329.08 rows=1 width=4) (actual time=29819.293..29819.295 rows=1 loops=1)
   ->  Nested Loop  (cost=978.97..1329.01 rows=22 width=4) (actual time=2.575..29815.530 rows=2056 loops=1)
         ->  Index Scan using forum_name on forum  (cost=0.00..242.39 rows=1 width=13) (actual time=0.016..0.355 rows=62 loops=1)
               Filter: ((permission & 4) = permission)
         ->  Bitmap Heap Scan on post  (cost=978.97..1086.28 rows=27 width=14) (actual time=97.997..480.746 rows=33 loops=62)
               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=91.106..91.106 rows=0 loops=62)
                     ->  Bitmap Index Scan on idx_message  (cost=0.00..370.57 rows=1435 width=0) (actual time=0.680..0.680 rows=2099 loops=62)
                           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=89.927..89.927 rows=22980 loops=62)
                           Index Cond: (post.forum = forum.name)
 Total runtime: 29819.376 ms
(13 rows)

ticker=#

The problem appearsa to lie in the "nested loop", and I don't understand why that's happening.  Isn't a **LINEAR** check on each returned value (since we do the aggregate first?) sufficient?  Why is the query planner creating a nested loop - the aggregate contains the tested field and it is not subject to change once aggregated?!


--------------050103040001030800070503-- --------------060703030907070804000005 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 --------------060703030907070804000005--