Received: from maia.hub.org (unknown [200.46.204.183]) by mail.postgresql.org (Postfix) with ESMTP id 22753633353 for ; Fri, 12 Feb 2010 12:44:54 -0400 (AST) Received: from mail.postgresql.org ([200.46.204.86]) by maia.hub.org (mx1.hub.org [200.46.204.183]) (amavisd-maia, port 10024) with ESMTP id 85367-01 for ; Fri, 12 Feb 2010 16:44:43 +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 EC21963285F for ; Fri, 12 Feb 2010 12:44:42 -0400 (AST) Received: from [127.0.0.1] (localhost [127.0.0.1]) by FS.denninger.net (8.14.3/8.13.1) with SMTP id o1CGigNn004307 for ; Fri, 12 Feb 2010 10:44:43 -0600 (CST) (envelope-from karl@denninger.net) Received: from [127.0.0.1] [192.168.1.40] by Spamblock-sys (LOCAL); Fri Feb 12 10:44:42 2010 Message-ID: <4B75851E.6070909@denninger.net> Date: Fri, 12 Feb 2010 10:43:10 -0600 From: Karl Denninger User-Agent: Thunderbird 2.0.0.23 (Windows/20090812) MIME-Version: 1.0 To: Kevin Grittner CC: Bryce Nesbitt , pgsql-performance@postgresql.org Subject: Re: 512,600ms query becomes 7500ms... but why? Postgres 8.3 query planner quirk? References: <4B723042.7090406@obviously.com> <4B751AD5020000250002F248@gw.wicourts.gov> <4B757C59.8070500@denninger.net> <4B752934020000250002F24E@gw.wicourts.gov> In-Reply-To: <4B752934020000250002F24E@gw.wicourts.gov> X-Enigmail-Version: 0.96.0 Content-Type: multipart/mixed; boundary="------------020800060802040908020106" X-Antivirus: avast! (VPS 100212-0, 02/12/2010), Outbound message X-Antivirus-Status: Clean X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=-0.084 tagged_above=-10 required=5 tests=BAYES_40=-0.185, HTML_MESSAGE=0.001, RDNS_DYNAMIC=0.1 X-Spam-Level: X-Archive-Number: 201002/208 X-Sequence-Number: 37629 This is a multi-part message in MIME format. --------------020800060802040908020106 Content-Type: multipart/alternative; boundary="------------050909050607070301060004" --------------050909050607070301060004 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Yes: select forum, * from post where marked is not true and toppost = 1 and (select login from ignore_thread where login='xxx' and number=post.number) is null and (replied > now() - '30 days'::interval) and (replied > (select lastview from forumlog where login='xxx' and forum=post.forum and number is null)) is not false and (replied > (select lastview from forumlog where login='xxx' and forum=post.forum and number=post.number)) is not false and ((post.forum = (select who from excludenew where who='xxx' and forum_name = post.forum)) or (select who from excludenew where who='xxx' and forum_name = post.forum) is null) order by pinned desc, replied desc offset 0 limit 100 Returns the following query plan: QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=5301575.63..5301575.63 rows=1 width=433) (actual time=771.000..771.455 rows=100 loops=1) -> Sort (cost=5301575.63..5301575.63 rows=1 width=433) (actual time=770.996..771.141 rows=100 loops=1) Sort Key: post.pinned, post.replied Sort Method: top-N heapsort Memory: 120kB -> Index Scan using post_top on post (cost=0.00..5301575.62 rows=1 width=433) (actual time=0.664..752.994 rows=3905 loops=1) Index Cond: (toppost = 1) Filter: ((marked IS NOT TRUE) AND (replied > (now() - '30 days'::interval)) AND ((SubPlan 1) IS NULL) AND ((replied > (SubPlan 2)) IS NOT FALSE) AND ((replied > (SubPlan 3)) IS NOT FALSE) AND ((forum = (SubPlan 4)) OR ((SubPlan 5) IS NULL))) SubPlan 1 -> Seq Scan on ignore_thread (cost=0.00..5.45 rows=1 width=7) (actual time=0.037..0.037 rows=0 loops=3905) Filter: ((login = 'xxx'::text) AND (number = $0)) SubPlan 2 -> Index Scan using forumlog_composite on forumlog (cost=0.00..9.50 rows=1 width=8) (actual time=0.008..0.008 rows=0 loops=3905) Index Cond: ((login = 'xxx'::text) AND (forum = $1) AND (number IS NULL)) SubPlan 3 -> Index Scan using forumlog_composite on forumlog (cost=0.00..9.50 rows=1 width=8) (actual time=0.006..0.006 rows=0 loops=3905) Index Cond: ((login = 'xxx'::text) AND (forum = $1) AND (number = $0)) SubPlan 4 -> Index Scan using excludenew_pkey on excludenew (cost=0.00..8.27 rows=1 width=9) (actual time=0.004..0.004 rows=0 loops=3905) Index Cond: ((who = 'xxx'::text) AND (forum_name = $1)) SubPlan 5 -> Index Scan using excludenew_pkey on excludenew (cost=0.00..8.27 rows=1 width=9) (actual time=0.004..0.004 rows=0 loops=3905) Index Cond: ((who = 'xxx'::text) AND (forum_name = $1)) Total runtime: 771.907 ms (23 rows) The alternative: select forum, * from post where marked is not true and toppost = 1 and not exists (select login from ignore_thread where login='xxx' and number=post.number) and (replied > now() - '30 days'::interval) and (replied > (select lastview from forumlog where login='xxx' and forum=post.forum and number is null)) is not false and (replied > (select lastview from forumlog where login='xxx' and forum=post.forum and number=post.number)) is not false and ((post.forum = (select who from excludenew where who='xxx' and forum_name = post.forum)) or (select who from excludenew where who='xxx' and forum_name = post.forum) is null) order by pinned desc, replied desc offset 0 limit 100 goes nuts. (Yes, I know, most of those others which are "not false" could be "Exists" too) Explain Analyze on the alternative CLAIMS the same query planner time (within a few milliseconds) with explain analyze. But if I replace the executing code with one that has the alternative ("not exists") syntax in it, the system load goes to crap instantly and the execution times "in the wild" go bananas. I don't know why it does - I just know THAT it does. When I first added that top clause in there (to allow people an individual "ignore thread" list) the system load went bananas immediately and forced me to back it out. When I re-wrote the query as above the performance was (and remains) fine. I'm running 8.4.2. I agree (in advance) it shouldn't trash performance - all I know is that it does and forced me to re-write the query. Kevin Grittner wrote: > Karl Denninger wrote: > Kevin Grittner wrote: > > >>> I suspect that the above might do pretty well in 8.4. >>> > > >> "Exists" can be quite slow. So can "not exists" >> >> See if you can re-write it using a sub-select - just replace the >> "exists ...." with "(select ...) is not null" >> >> Surprisingly this often results in a MUCH better query plan under >> Postgresql. Why the planner evaluates it "better" eludes me (it >> shouldn't) but the differences are often STRIKING - I've seen >> factor-of-10 differences in execution performance. >> > > Have you seen such a difference under 8.4? Can you provide a > self-contained example? > > -Kevin > > --------------050909050607070301060004 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Yes:

select forum, * from post where
    marked is not true
    and toppost = 1
    and (select login from ignore_thread where login='xxx' and number=post.number) is null
    and (replied > now() - '30 days'::interval)
    and (replied > (select lastview from forumlog where login='xxx' and forum=post.forum and number is null)) is not false
    and (replied > (select lastview from forumlog where login='xxx' and forum=post.forum and number=post.number)) is not false
    and ((post.forum = (select who from excludenew where who='xxx' and forum_name = post.forum)) or (select who from excludenew where who='xxx' and forum_name = post.forum) is null)
   order by pinned desc, replied desc offset 0 limit 100

Returns the following query plan:
                                                              QUERY PLAN                                                                                                                           
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=5301575.63..5301575.63 rows=1 width=433) (actual time=771.000..771.455 rows=100 loops=1)
   ->  Sort  (cost=5301575.63..5301575.63 rows=1 width=433) (actual time=770.996..771.141 rows=100 loops=1)
         Sort Key: post.pinned, post.replied
         Sort Method:  top-N heapsort  Memory: 120kB
         ->  Index Scan using post_top on post  (cost=0.00..5301575.62 rows=1 width=433) (actual time=0.664..752.994 rows=3905 loops=1)
               Index Cond: (toppost = 1)
               Filter: ((marked IS NOT TRUE) AND (replied > (now() - '30 days'::interval)) AND ((SubPlan 1) IS NULL) AND ((replied > (SubPlan 2)) IS NOT FALSE) AND ((replied > (SubPlan 3)) IS NOT FALSE) AND ((forum = (SubPlan 4)) OR ((SubPlan 5) IS NULL)))
               SubPlan 1
                 ->  Seq Scan on ignore_thread  (cost=0.00..5.45 rows=1 width=7) (actual time=0.037..0.037 rows=0 loops=3905)
                       Filter: ((login = 'xxx'::text) AND (number = $0))
               SubPlan 2
                 ->  Index Scan using forumlog_composite on forumlog  (cost=0.00..9.50 rows=1 width=8) (actual time=0.008..0.008 rows=0 loops=3905)
                       Index Cond: ((login = 'xxx'::text) AND (forum = $1) AND (number IS NULL))
               SubPlan 3
                 ->  Index Scan using forumlog_composite on forumlog  (cost=0.00..9.50 rows=1 width=8) (actual time=0.006..0.006 rows=0 loops=3905)
                       Index Cond: ((login = 'xxx'::text) AND (forum = $1) AND (number = $0))
               SubPlan 4
                 ->  Index Scan using excludenew_pkey on excludenew  (cost=0.00..8.27 rows=1 width=9) (actual time=0.004..0.004 rows=0 loops=3905)
                       Index Cond: ((who = 'xxx'::text) AND (forum_name = $1))
               SubPlan 5
                 ->  Index Scan using excludenew_pkey on excludenew  (cost=0.00..8.27 rows=1 width=9) (actual time=0.004..0.004 rows=0 loops=3905)
                       Index Cond: ((who = 'xxx'::text) AND (forum_name = $1))
 Total runtime: 771.907 ms
(23 rows)

The alternative:

select forum, * from post where
    marked is not true
    and toppost = 1
    and not exists (select login from ignore_thread where login='xxx' and number=post.number)
    and (replied > now() - '30 days'::interval)
    and (replied > (select lastview from forumlog where login='xxx' and forum=post.forum and number is null)) is not false
    and (replied > (select lastview from forumlog where login='xxx' and forum=post.forum and number=post.number)) is not false
    and ((post.forum = (select who from excludenew where who='xxx' and forum_name = post.forum)) or (select who from excludenew where who='xxx' and forum_name = post.forum) is null)
   order by pinned desc, replied desc offset 0 limit 100

goes nuts.

(Yes, I know, most of those others which are "not false" could be "Exists" too)

Explain Analyze on the alternative CLAIMS the same query planner time (within a few milliseconds) with explain analyze.  But if I replace the executing code with one that has the alternative ("not exists") syntax in it, the system load goes to crap instantly and the execution times "in the wild" go bananas.

I don't know why it does - I just know THAT it does.  When I first added that top clause in there (to allow people an individual "ignore thread" list) the system load went bananas immediately and forced me to back it out.   When I re-wrote the query as above the performance was (and remains) fine.

I'm running 8.4.2.

I agree (in advance) it shouldn't trash performance - all I know is that it does and forced me to re-write the query.


Kevin Grittner wrote: 
Karl Denninger <karl@denninger.net> wrote:
Kevin Grittner wrote:
 
  
I suspect that the above might do pretty well in 8.4.
      
 
  
"Exists" can be quite slow.  So can "not exists"

See if you can re-write it using a sub-select - just replace the
"exists ...." with "(select ...) is not null"

Surprisingly this often results in a MUCH better query plan under
Postgresql.  Why the planner evaluates it "better" eludes me (it
shouldn't) but the differences are often STRIKING - I've seen
factor-of-10 differences in execution performance.
    
 
Have you seen such a difference under 8.4?  Can you provide a
self-contained example?
 
-Kevin
--------------050909050607070301060004-- --------------020800060802040908020106 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 email;internet:karl@denninger.net x-mozilla-html:TRUE version:2.1 end:vcard --------------020800060802040908020106--