Received: from maia.hub.org (unknown [200.46.204.183]) by mail.postgresql.org (Postfix) with ESMTP id 324B763413C for ; Fri, 19 Mar 2010 14:02:18 -0300 (ADT) 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 92293-07 for ; Fri, 19 Mar 2010 17:02:07 +0000 (UTC) X-Greylist: domain auto-whitelisted by SQLgrey-1.7.6 Received: from mail-pv0-f174.google.com (mail-pv0-f174.google.com [74.125.83.174]) by mail.postgresql.org (Postfix) with ESMTP id 2F2A163302F for ; Fri, 19 Mar 2010 14:02:07 -0300 (ADT) Received: by pva4 with SMTP id 4so1698833pva.19 for ; Fri, 19 Mar 2010 10:02:05 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=domainkey-signature:mime-version:received:in-reply-to:references :date:message-id:subject:from:to:content-type; bh=OkMbnT5BP1aCd7jk9zEuflKZKBP7/oyltBo56lnNPiY=; b=FookJKRX0kljZm4NL++nENlPwkp7h/nsT1ITPSQdjsz9OTjpcskcX4PMY4ziBOa1z+ hWxKe3FtDdqdra6H8z7BltaMirJ3QS6LWp2BTicyhrV6lv95sb3SaU9izsHhA3YvBh98 AQ6Cc8Ibjf5nhP5f4i0nHHmo4XfxtH0OUHJN4= DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=mime-version:in-reply-to:references:date:message-id:subject:from:to :content-type; b=eNF5gF54zBZUzxFKAfe2SUWvHyEc337s4SugBs0uVogLDXrqiX7zsczFRCYAefxpJF PGc5gFNLrNms5wKQGACSWG8p/z8kjJWzly4B4I4kuyHyHIuq1CISA4iIEa+2U+mMc81e mVTs8osBk1W9ggyHvGcPgusrLv7mXWNti1vt0= MIME-Version: 1.0 Received: by 10.142.55.18 with SMTP id d18mr189424wfa.170.1269018125603; Fri, 19 Mar 2010 10:02:05 -0700 (PDT) In-Reply-To: <16083557406886@mail.magwerks.com> References: <16083557406886@mail.magwerks.com> Date: Fri, 19 Mar 2010 13:02:05 -0400 Message-ID: <36f7b6b51003191002h5c6ad9cfhe0a2e7e7a328d5ae@mail.gmail.com> Subject: Re: too complex query plan for not exists query and multicolumn indexes From: Justin Graf To: wakathane@gmail.com, pgsql-performance@postgresql.org Content-Type: multipart/alternative; boundary=001636b2bb879714f804822a4ed4 X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=-2.598 tagged_above=-10 required=5 tests=BAYES_00=-2.599, HTML_MESSAGE=0.001 X-Spam-Level: X-Archive-Number: 201003/278 X-Sequence-Number: 38103 --001636b2bb879714f804822a4ed4 Content-Type: text/plain; charset=ISO-8859-1 ---- Message from Corin at 03-19-2010 01:26:35 PM ------ ***snip **** The intention of the query is to find rows with no "partner" row. The offset and limit are just to ignore the time needed to send the result to the client. ------- I don't understand the point of OFFSET, limit will accomplish the same thing, PG will still execute the query the only difference is PG will skip the step to count through the first million rows before returning a record. ------- SELECT * FROM friends AS f1 WHERE NOT EXISTS (SELECT 1 FROM friends AS f2 WHERE f1.user_id=f2.ref_id AND f1.ref_id=f2.user_id) OFFSET 1000000 LIMIT 1 Mysql uses this query plan: 1 PRIMARY f1 index NULL user_ref 8 NULL 2818860 Using where; Using index 2 DEPENDENT SUBQUERY f2 ref user_ref user_ref 8 f1.ref_id,f1.user_id 1 Using index Time: 9.8s ------- if that's a query explain in Mysql its worthless. The above has no information, does not tell us how long each step is taking, let alone what it was thinking it would take to make the query work . ------ Postgre uses this query plan: "Limit (cost=66681.50..66681.50 rows=1 width=139) (actual time=7413.489..7413.489 rows=1 loops=1)" " -> Merge Anti Join (cost=40520.17..66681.50 rows=367793 width=139) (actual time=3705.078..7344.256 rows=1000001 loops=1)" " *Merge Cond: ((f1.user_id = f2.ref_id) AND (f1.ref_id = f2.user_id))"* " -> Index Scan using user_ref on friends f1 (cost=0.00..26097.86 rows=2818347 width=139) (actual time=0.093..1222.592 rows=1917360 loops=1)" " -> Materialize (cost=40520.17..40555.40 rows=2818347 width=8) (actual time=3704.977..5043.347 rows=1990148 loops=1)" " -> Sort (cost=40520.17..40527.21 rows=2818347 width=8) (actual time=3704.970..4710.703 rows=1990148 loops=1)" " Sort Key: f2.ref_id, f2.user_id" " Sort Method: external merge Disk: 49576kB" " -> Seq Scan on friends f2 (cost=0.00..18143.18 rows=2818347 width=8) (actual time=0.015..508.797 rows=2818347 loops=1)" "Total runtime: 7422.516 ms" --- We can see each step PG takes and make inform decisions what part of the query is slow . We can See the Sorting the rows takes most of the time --- It's already faster, which is great, but I wonder why the query plan is that complex. ---- Its not complex it showing you all the steps which Mysql is not showing you ---- I read in the pqsql docs that using a multicolumn key is almost never needed and only a waste of cpu/space. So I dropped the multicolumn key and added to separate keys instead: ---- Where is that at??? I don't recall reading that. PG will only use indexes that match exactly where/join conditions. ---- CREATE INDEX ref1 ON friends USING btree (ref_id); CREATE INDEX user1 ON friends USING btree (user_id); New query plan: "Limit (cost=70345.04..70345.04 rows=1 width=139) (actual time=43541.709..43541.709 rows=1 loops=1)" " -> Merge Anti Join (cost=40520.27..70345.04 rows=367793 width=139) (actual time=3356.694..43467.818 rows=1000001 loops=1)" " * Merge Cond: (f1.user_id = f2.ref_id)" " Join Filter: (f1.ref_id = f2.user_id)" --- *take note the merge has changed. it now joins on f1.user_id=f2.ref_id then filters the results down by using the AND condition. Put the index back * --- *" -> Index Scan using user1 on friends f1 (cost=0.00..26059.79 rows=2818347 width=139) (actual time=0.031..1246.668 rows=1917365 loops=1)" " -> Materialize (cost=40520.17..40555.40 rows=2818347 width=8) (actual time=3356.615..14941.405* rows=130503729* loops=1)" --- take note look at what happened here. this because the of Join is not limited as it was before. did you run this query against Mysql with the same kind of indexes??? ----- " -> Sort (cost=40520.17..40527.21 rows=2818347 width=8) (actual time=3356.611..4127.435 rows=1990160 loops=1)" " Sort Key: f2.ref_id" " Sort Method: external merge Disk: 49560kB" " -> Seq Scan on friends f2 (cost=0.00..18143.18 rows=2818347 width=8) (actual time=0.012..496.174 rows=2818347 loops=1)" "Total runtime: 43550.187 ms" I also wonder why it makes a difference when adding a "LIMIT" clause to the subselect in an EXISTS subselect. Shouldn't pgsql always stop after finding the a row? In mysql is makes no difference in speed, pgsql even get's slower when adding a LIMIT to the EXISTS subselect (I hoped it would get faster?!). ---- Limits occur last after doing all the major work is done ---- SELECT * FROM friends AS f1 WHERE NOT EXISTS (SELECT 1 FROM friends AS f2 WHERE f1.user_id=f2.ref_id AND f1.ref_id=f2.user_id LIMIT 1) OFFSET 1000000 LIMIT 1 "Limit (cost=6389166.19..6389172.58 rows=1 width=139) (actual time=54540.356..54540.356 rows=1 loops=1)" " -> Seq Scan on friends f1 (cost=0.00..9003446.87 rows=1409174 width=139) (actual time=0.511..54460.006 rows=1000001 loops=1)" " Filter: (NOT (SubPlan 1))" " * SubPlan 1" " -> Limit (cost=2.18..3.19 rows=1 width=0) (actual time=0.029..0.029 rows=0 loops=1832284)"* --- this caused PG to create a subplan which resulted in a more complex plan PG is doing lots more work --- " -> Bitmap Heap Scan on friends f2 (cost=2.18..3.19 rows=1 width=0) (actual time=0.028..0.028 rows=0 loops=1832284)" " Recheck Cond: (($0 = ref_id) AND ($1 = user_id))" " -> BitmapAnd (cost=2.18..2.18 rows=1 width=0) (actual time=0.027..0.027 rows=0 loops=1832284)" " -> Bitmap Index Scan on ref1 (cost=0.00..1.09 rows=75 width=0) (actual time=0.011..0.011 rows=85 loops=1832284)" " Index Cond: ($0 = ref_id)" " -> Bitmap Index Scan on user1 (cost=0.00..1.09 rows=87 width=0) (actual time=0.011..0.011 rows=87 loops=1737236)" " Index Cond: ($1 = user_id)" "Total runtime: 54540.431 ms" --- this plan is not even close to the others --- --001636b2bb879714f804822a4ed4 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable
---- Message from Corin <waka= thane@gmail.com> at 03-19-2010 01:26:35 PM ------

***snip ***= *
The intention of the query is to find rows with no "partner"= row. The
offset and limit are just to ignore the time needed to send the result
t= o the client.
-------
I don= 9;t understand the point of OFFSET, =A0limit will accomplish the same thing= , =A0PG will still execute the query the only difference is PG will skip th= e step to count through the first million rows before returning a record. = =A0
-------

SELECT * FROM friends AS f1 WHERE NOT EXISTS (SELECT 1 FROM = friends AS
f2 WHERE f1.user_id=3Df2.ref_id AND f1.ref_id=3Df2.user_id) O= FFSET 1000000
LIMIT 1

Mysql uses this query plan:
1 =A0=A0=A0= =A0PRIMARY =A0=A0=A0=A0f1 =A0=A0=A0=A0index =A0=A0=A0=A0=A0NULL =A0=A0=A0= =A0user_ref =A0=A0=A0=A08 =A0=A0=A0=A0=A0NULL
=A0=A0=A0=A02818860 =A0=A0=A0=A0Using where; Using index
2 =A0=A0=A0=A0D= EPENDENT SUBQUERY =A0=A0=A0=A0f2 =A0=A0=A0=A0ref =A0=A0=A0=A0user_ref =A0= =A0=A0=A0user_ref =A0=A0=A0=A08
=A0=A0=A0=A0f1.ref_id,f1.user_id =A0=A0= =A0=A01 =A0=A0=A0=A0Using index
Time: 9.8s

-------
if that's a query explain in Mysql its wort= hless. The above =A0has no information, does not tell us how long each step= is taking, let alone what it was thinking it would take to make the query = work .
------

Postgre uses this query plan:
"Limit =A0(cost=3D66681= .50..66681.50 rows=3D1 width=3D139) (actual
time=3D7413.489..7413.489 ro= ws=3D1 loops=3D1)"
" =A0-> =A0Merge Anti Join =A0(cost=3D40= 520.17..66681.50 rows=3D367793 width=3D139)
(actual time=3D3705.078..7344.256 rows=3D1000001 loops=3D1)"
"= =A0=A0=A0=A0=A0=A0=A0Merge Cond: ((f1.user_id =3D f2.ref_id) AND (f1.re= f_id =3D
f2.user_id))"
" =A0=A0=A0=A0=A0=A0=A0-> =A0= Index Scan using user_ref on friends f1 =A0
(cost=3D0.00..26097.86 rows=3D2818347 width=3D139) (actual
time=3D0.093.= .1222.592 rows=3D1917360 loops=3D1)"
" =A0=A0=A0=A0=A0=A0=A0-&= gt; =A0Materialize =A0(cost=3D40520.17..40555.40 rows=3D2818347 width=3D8)<= br>(actual time=3D3704.977..5043.347 rows=3D1990148 loops=3D1)"
" =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0-> =A0Sort =A0(cost=3D4052= 0.17..40527.21 rows=3D2818347 width=3D8)
(actual time=3D3704.970..4710.7= 03 rows=3D1990148 loops=3D1)"
" =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0Sort Key: f2.ref_id, f2.user_id"
" = =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0Sort Method: =A0ex= ternal merge =A0Disk: 49576kB"
" =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0-> =A0Se= q Scan on friends f2 =A0(cost=3D0.00..18143.18
rows=3D2818347 width=3D8)= (actual time=3D0.015..508.797 rows=3D2818347 loops=3D1)"
"Tot= al runtime: 7422.516 ms"

---
We can see each step = PG takes and make inform decisions what part of the query is slow . =A0We c= an See the Sorting the rows takes most of the time
---

It's already faster, which is great, but I wonder why the qu= ery plan is
that complex.

----
Its not complex it showing you all the steps which Mysql is not sho= wing you
----

I read in the pqsql docs that using a multicolumn key is almost= never
needed and only a waste of cpu/space. So I dropped the multicolum= n key
and added to separate keys instead:

----
Where is that at??? =A0I don't recall reading t= hat.=A0 PG will only use indexes that match exactly where/join conditions. =

----

CREATE INDEX ref1 ON friends USING btree (ref_id);
CREAT= E INDEX user1 ON friends USING btree (user_id);

New query plan:
&= quot;Limit =A0(cost=3D70345.04..70345.04 rows=3D1 width=3D139) (actual
t= ime=3D43541.709..43541.709 rows=3D1 loops=3D1)"
" =A0-> =A0Merge Anti Join =A0(cost=3D40520.27..70345.04 rows=3D367= 793 width=3D139)
(actual time=3D3356.694..43467.818 rows=3D1000001 loops= =3D1)"
" =A0=A0=A0=A0=A0=A0=A0Merge Cond: (f1.user_id =3D f= 2.ref_id)"
" =A0=A0=A0=A0=A0=A0=A0Join Filter: (f1.ref_id =3D = f2.user_id)"
---
take note the merge has c= hanged.=A0 it now joins on f1.user_id=3Df2.ref_id then filters the results = down by using the AND condition. Put the index back
---
" =A0=A0=A0=A0=A0=A0=A0-> =A0Index Scan using user1 on friends f1= =A0(cost=3D0.00..26059.79
rows=3D2818347 width=3D139) (actual time=3D0.031..1246.668 rows=3D1917365 l= oops=3D1)"
" =A0=A0=A0=A0=A0=A0=A0-> =A0Materialize =A0(cos= t=3D40520.17..40555.40 rows=3D2818347 width=3D8)
(actual time=3D3356.615= ..14941.405 rows=3D130503729 loops=3D1)"= ;
---
take note look at what happen= ed here. this because the of Join is not limited as it was before.
did = you run this query against Mysql with the same kind of indexes??? -----
" =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0-> =A0Sort =A0(co= st=3D40520.17..40527.21 rows=3D2818347 width=3D8)
(actual time=3D3356.61= 1..4127.435 rows=3D1990160 loops=3D1)"
" =A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0Sort Key: f2.ref_id"
" =A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0Sort Method: =A0exter= nal merge =A0Disk: 49560kB"
" =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0-> =A0Se= q Scan on friends f2 =A0(cost=3D0.00..18143.18
rows=3D2818347 width=3D8)= (actual time=3D0.012..496.174 rows=3D2818347 loops=3D1)"
"Tot= al runtime: 43550.187 ms"

I also wonder why it makes a differen= ce when adding a "LIMIT" clause to
the subselect in an EXISTS subselect. Shouldn't pgsql always stop after=
finding the a row? In mysql is makes no difference in speed, pgsql even=
get's slower when adding a LIMIT to the EXISTS subselect (I hoped i= t
would get faster?!).


----=
Limits occur last after doing all the major work=A0 is done
----


SELECT * FROM friends AS f1 WHERE NOT EXISTS (SELECT= 1 FROM friends AS
f2 WHERE f1.user_id=3Df2.ref_id AND f1.ref_id=3Df2.us= er_id LIMIT 1) OFFSET
1000000 LIMIT 1

"Limit =A0(cost=3D6389= 166.19..6389172.58 rows=3D1 width=3D139) (actual
time=3D54540.356..54540.356 rows=3D1 loops=3D1)"
" =A0-> = =A0Seq Scan on friends f1 =A0(cost=3D0.00..9003446.87 rows=3D1409174
wid= th=3D139) (actual time=3D0.511..54460.006 rows=3D1000001 loops=3D1)"" =A0=A0=A0=A0=A0=A0=A0Filter: (NOT (SubPlan 1))"
" =A0=A0=A0=A0=A0=A0=A0SubPlan 1"
" =A0=A0=A0=A0=A0=A0= =A0=A0=A0-> =A0Limit =A0(cost=3D2.18..3.19 rows=3D1 width=3D0) (actualtime=3D0.029..0.029 rows=3D0 loops=3D1832284)"
---
this caused PG to create a subplan which re= sulted in a more complex plan
PG is doing lots more work
---
" =A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0-> =A0Bitmap Heap Scan on friends f2 =A0(cost=3D= 2.18..3.19
rows=3D1 width=3D0) (actual time=3D0.028..0.028 rows=3D0 loop= s=3D1832284)"
" =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0Recheck Cond: (($0 =3D ref_id) AND ($1 =3D user_id))"= ;
" =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0->= =A0BitmapAnd =A0(cost=3D2.18..2.18 rows=3D1 width=3D0)
(actual time=3D0= .027..0.027 rows=3D0 loops=3D1832284)"
" =A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0-> =A0Bitmap= Index Scan on ref1 =A0
(cost=3D0.00..1.09 rows=3D75 width=3D0) (actual = time=3D0.011..0.011 rows=3D85
loops=3D1832284)"
" =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0Index Cond: ($0 = =3D ref_id)"
" =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0-> =A0Bitmap Index Scan on user1 =A0=
(cost=3D0.00..1.09 rows=3D87 width=3D0) (actual time=3D0.011..0.011 row= s=3D87
loops=3D1737236)"
" =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0Index Cond: ($1 = =3D user_id)"
"Total runtime: 54540.431 ms"

---this plan is not even close to the = others
---



--001636b2bb879714f804822a4ed4--