Received: from localhost (unknown [200.46.208.211]) by mail.postgresql.org (Postfix) with ESMTP id 29E8B632D81 for ; Tue, 18 Aug 2009 18:00:03 -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 75986-04 for ; Tue, 18 Aug 2009 20:59:47 +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 5CC546322F1 for ; Tue, 18 Aug 2009 17:59:50 -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 n7IKxnwH056150 for ; Tue, 18 Aug 2009 15:59:50 -0500 (CDT) (envelope-from karl@denninger.net) Received: from [127.0.0.1] [192.168.1.40] by Spamblock-sys (LOCAL); Tue Aug 18 15:59:50 2009 Message-ID: <4A8B1606.2040209@denninger.net> Date: Tue, 18 Aug 2009 15:58:46 -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> In-Reply-To: <4A8AC75C0200002500029C8A@gw.wicourts.gov> X-Enigmail-Version: 0.96.0 Content-Type: multipart/mixed; boundary="------------040803000100010508060608" X-Antivirus: avast! (VPS 090817-0, 08/17/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/195 X-Sequence-Number: 35227 This is a multi-part message in MIME format. --------------040803000100010508060608 Content-Type: multipart/alternative; boundary="------------040409070602020509020506" --------------040409070602020509020506 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit 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 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 > > --------------040409070602020509020506 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit 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
--------------040409070602020509020506-- --------------040803000100010508060608 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 --------------040803000100010508060608--