Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtp (Exim 4.72) (envelope-from ) id 1TGwUz-0007HH-1I; Wed, 26 Sep 2012 18:38:17 +0000 Received: from smtp120.dfw.emailsrvr.com ([67.192.241.120]) by magus.postgresql.org with esmtp (Exim 4.72) (envelope-from ) id 1TGwUv-0006CQ-7Q; Wed, 26 Sep 2012 18:38:16 +0000 Received: from smtp22.relay.dfw1a.emailsrvr.com (localhost.localdomain [127.0.0.1]) by smtp22.relay.dfw1a.emailsrvr.com (SMTP Server) with ESMTP id 5A472170FCD; Wed, 26 Sep 2012 14:38:11 -0400 (EDT) X-SMTPDoctor-Processed: csmtpprox 2.7.4 Received: from localhost (localhost.localdomain [127.0.0.1]) by smtp22.relay.dfw1a.emailsrvr.com (SMTP Server) with ESMTP id 540D3170FC2; Wed, 26 Sep 2012 14:38:11 -0400 (EDT) X-Virus-Scanned: OK Received: by smtp22.relay.dfw1a.emailsrvr.com (Authenticated sender: rsosinski-AT-ticketevolution.com) with ESMTPSA id C7F72170EF9; Wed, 26 Sep 2012 14:38:10 -0400 (EDT) Date: Wed, 26 Sep 2012 14:38:09 -0400 From: Robert Sosinski To: pgsql-general@postgresql.org, pgsql-performance@postgresql.org Cc: Spike Grobstein Message-ID: Subject: Inaccurate Explain Cost X-Mailer: sparrow 1.6.4 (build 1176) MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="50634b91_46b7d447_ec0f" X-Pg-Spam-Score: -1.0 (-) X-Archive-Number: 201209/142 X-Sequence-Number: 47888 --50634b91_46b7d447_ec0f Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: 7bit Content-Disposition: inline Hey Everyone, I seem to be getting an inaccurate cost from explain. Here are two examples for one query with two different query plans: exchange_prod=# set enable_nestloop = on; SET exchange_prod=# exchange_prod=# explain analyze SELECT COUNT(DISTINCT "exchange_uploads"."id") FROM "exchange_uploads" INNER JOIN "upload_destinations" ON "upload_destinations"."id" = "exchange_uploads"."upload_destination_id" LEFT OUTER JOIN "uploads" ON "uploads"."id" = "exchange_uploads"."upload_id" LEFT OUTER JOIN "import_errors" ON "import_errors"."exchange_upload_id" = "exchange_uploads"."id" LEFT OUTER JOIN "exchanges" ON "exchanges"."id" = "upload_destinations"."exchange_id" WHERE (("exchange_uploads"."created_at" >= '2012-07-27 21:21:57.363944' AND "upload_destinations"."office_id" = 6)); QUERY PLAN --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Aggregate (cost=190169.54..190169.55 rows=1 width=4) (actual time=199806.806..199806.807 rows=1 loops=1) -> Nested Loop Left Join (cost=0.00..190162.49 rows=2817 width=4) (actual time=163.293..199753.548 rows=43904 loops=1) -> Nested Loop (cost=0.00..151986.53 rows=2817 width=4) (actual time=163.275..186869.844 rows=43904 loops=1) -> Index Scan using upload_destinations_office_id_idx on upload_destinations (cost=0.00..29.95 rows=4 width=8) (actual time=0.060..0.093 rows=6 loops=1) Index Cond: (office_id = 6) -> Index Scan using index_exchange_uploads_on_upload_destination_id on exchange_uploads (cost=0.00..37978.21 rows=875 width=12) (actual time=27.197..31140.375 rows=7317 loops=6) Index Cond: (upload_destination_id = upload_destinations.id) Filter: (created_at >= '2012-07-27 21:21:57.363944'::timestamp without time zone) -> Index Scan using index_import_errors_on_exchange_upload_id on import_errors (cost=0.00..8.49 rows=405 width=4) (actual time=0.291..0.291 rows=0 loops=43904) Index Cond: (exchange_upload_id = exchange_uploads.id) Total runtime: 199806.951 ms (11 rows) exchange_prod=# exchange_prod=# set enable_nestloop = off; SET exchange_prod=# exchange_prod=# explain analyze SELECT COUNT(DISTINCT "exchange_uploads"."id") FROM "exchange_uploads" INNER JOIN "upload_destinations" ON "upload_destinations"."id" = "exchange_uploads"."upload_destination_id" LEFT OUTER JOIN "uploads" ON "uploads"."id" = "exchange_uploads"."upload_id" LEFT OUTER JOIN "import_errors" ON "import_errors"."exchange_upload_id" = "exchange_uploads"."id" LEFT OUTER JOIN "exchanges" ON "exchanges"."id" = "upload_destinations"."exchange_id" WHERE (("exchange_uploads"."created_at" >= '2012-07-27 21:21:57.363944' AND "upload_destinations"."office_id" = 6)); QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Aggregate (cost=2535992.33..2535992.34 rows=1 width=4) (actual time=133447.507..133447.507 rows=1 loops=1) -> Hash Right Join (cost=1816553.69..2535985.56 rows=2708 width=4) (actual time=133405.326..133417.078 rows=43906 loops=1) Hash Cond: (import_errors.exchange_upload_id = exchange_uploads.id) -> Seq Scan on import_errors (cost=0.00..710802.71 rows=2300471 width=4) (actual time=0.006..19199.569 rows=2321888 loops=1) -> Hash (cost=1816519.84..1816519.84 rows=2708 width=4) (actual time=112938.606..112938.606 rows=43906 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 1544kB -> Hash Join (cost=28.25..1816519.84 rows=2708 width=4) (actual time=42.957..112892.689 rows=43906 loops=1) Hash Cond: (exchange_uploads.upload_destination_id = upload_destinations.id) -> Index Scan using index_upload_destinations_on_created_at on exchange_uploads (cost=0.00..1804094.96 rows=3298545 width=12) (actual time=17.686..111649.272 rows=3303488 loops=1) Index Cond: (created_at >= '2012-07-27 21:21:57.363944'::timestamp without time zone) -> Hash (cost=28.20..28.20 rows=4 width=8) (actual time=0.043..0.043 rows=6 loops=1) Buckets: 1024 Batches: 1 Memory Usage: 1kB -> Bitmap Heap Scan on upload_destinations (cost=6.28..28.20 rows=4 width=8) (actual time=0.026..0.036 rows=6 loops=1) Recheck Cond: (office_id = 6) -> Bitmap Index Scan on upload_destinations_office_id_idx (cost=0.00..6.28 rows=4 width=0) (actual time=0.020..0.020 rows=6 loops=1) Index Cond: (office_id = 6) Total runtime: 133447.790 ms (17 rows) The first query shows a cost of 190,169.55 and runs in 199,806.951 ms. When I disable nested loop, I get a cost of 2,535,992.34 which runs in only 133,447.790 ms. We have run queries on our database with a cost of 200K cost before and they ran less then a few seconds, which makes me wonder if the first query plan is inaccurate. The other issue is understanding why a query plan with a much higher cost is taking less time to run. I do not think these queries are cached differently, as we have gotten the same results ran a couple of times at across a few days. We also analyzed the tables that we are querying before trying the explain analyze again, and were met with the same statistics. Any help on how Postgres comes up with a query plan like this, and why there is a difference would be very helpful. Thanks! -- Robert Sosinski --50634b91_46b7d447_ec0f Content-Type: text/html; charset="utf-8" Content-Transfer-Encoding: quoted-printable Content-Disposition: inline
Hey Everyone,

I seem to be getting an inaccur= ate cost from explain.  Here are two examples for one query with two= different query plans:

exchange=5Fprod=3D=23 set enable=5Fnestloop =3D on;<= /div>
SET
exchange=5Fprod=3D=23
exchange=5Fprod=3D=23 explain analyze SELECT = COUNT(DISTINCT =22exchange=5Fuploads=22.=22id=22) =46ROM =22exchange=5Fup= loads=22 INNER JOIN =22upload=5Fdestinations=22 ON =22upload=5Fdestinatio= ns=22.=22id=22 =3D =22exchange=5Fuploads=22.=22upload=5Fdestination=5Fid=22= LE=46T OUTER JOIN =22uploads=22 ON =22uploads=22.=22id=22 =3D =22exchang= e=5Fuploads=22.=22upload=5Fid=22 LE=46T OUTER JOIN =22import=5Ferrors=22 = ON =22import=5Ferrors=22.=22exchange=5Fupload=5Fid=22 =3D =22exchange=5Fu= ploads=22.=22id=22 LE=46T OUTER JOIN =22exchanges=22 ON =22exchanges=22.=22= id=22 =3D =22upload=5Fdestinations=22.=22exchange=5Fid=22 WHERE ((=22exch= ange=5Fuploads=22.=22created=5Fat=22 >=3D '2012-07-27 21:21:57.363944'= AND =22upload=5Fdestinations=22.=22office=5Fid=22 =3D 6));
&nb= sp;                    =                     &n= bsp;                    = ;                     &= nbsp;       QUERY PLAN           =                     &nb= sp;                    =                     &n= bsp;                   =
--------------------------------------------------------------= -------------------------------------------------------------------------= ------------------------------------------------------------
&n= bsp;Aggregate  (cost=3D190169.54..190169.55 rows=3D1 width=3D= 4) (actual time=3D199806.806..199806.807 rows=3D1 loops=3D1)
&n= bsp;  ->  Nested Loop Left Join  (cost=3D0.00..190162.4= 9 rows=3D2817 width=3D4) (actual time=3D163.293..199753.548 rows=3D43904 = loops=3D1)
         ->  Nested= Loop  (cost=3D0.00..151986.53 rows=3D2817 width=3D4) (actual time=3D= 163.275..186869.844 rows=3D43904 loops=3D1)
     = ;          ->  Index Scan using upload=5F= destinations=5Foffice=5Fid=5Fidx on upload=5Fdestinations  (cost=3D0= .00..29.95 rows=3D4 width=3D8) (actual time=3D0.060..0.093 rows=3D6 loops= =3D1)
                &= nbsp;    Index Cond: (office=5Fid =3D 6)
   = ;            ->  Index Scan using i= ndex=5Fexchange=5Fuploads=5Fon=5Fupload=5Fdestination=5Fid on exchange=5F= uploads  (cost=3D0.00..37978.21 rows=3D875 width=3D12) (actual time=3D= 27.197..31140.375 rows=3D7317 loops=3D6)
      &= nbsp;              Index Cond: (upload= =5Fdestination=5Fid =3D upload=5Fdestinations.id)
   =                  =46ilter: = (created=5Fat >=3D '2012-07-27 21:21:57.363944'::timestamp without tim= e zone)
         ->  Index Sca= n using index=5Fimport=5Ferrors=5Fon=5Fexchange=5Fupload=5Fid on import=5F= errors  (cost=3D0.00..8.49 rows=3D405 width=3D4) (actual time=3D0.29= 1..0.291 rows=3D0 loops=3D43904)
        &n= bsp;      Index Cond: (exchange=5Fupload=5Fid =3D exchange= =5Fuploads.id)
 Total runtime: 199806.951 ms
<= div>(11 rows)

exchange=5Fprod=3D=23 
<= div>exchange=5Fprod=3D=23 set enable=5Fnestloop =3D off;
SET
exchange=5Fprod=3D=23 
exchange=5Fprod=3D=23 expla= in analyze SELECT COUNT(DISTINCT =22exchange=5Fuploads=22.=22id=22) =46RO= M =22exchange=5Fuploads=22 INNER JOIN =22upload=5Fdestinations=22 ON =22u= pload=5Fdestinations=22.=22id=22 =3D =22exchange=5Fuploads=22.=22upload=5F= destination=5Fid=22 LE=46T OUTER JOIN =22uploads=22 ON =22uploads=22.=22i= d=22 =3D =22exchange=5Fuploads=22.=22upload=5Fid=22 LE=46T OUTER JOIN =22= import=5Ferrors=22 ON =22import=5Ferrors=22.=22exchange=5Fupload=5Fid=22 = =3D =22exchange=5Fuploads=22.=22id=22 LE=46T OUTER JOIN =22exchanges=22 O= N =22exchanges=22.=22id=22 =3D =22upload=5Fdestinations=22.=22exchange=5F= id=22 WHERE ((=22exchange=5Fuploads=22.=22created=5Fat=22 >=3D '2012-0= 7-27 21:21:57.363944' AND =22upload=5Fdestinations=22.=22office=5Fid=22 =3D= 6));
                &= nbsp;                   &nbs= p;                     =                     &nb= sp;                 QUERY PLAN &n= bsp;                    = ;                     &= nbsp;                   &nbs= p;                     =             
---------------= -------------------------------------------------------------------------= -------------------------------------------------------------------------= ------------------------------------------
 Aggregate &nbs= p;(cost=3D2535992.33..2535992.34 rows=3D1 width=3D4) (actual time=3D= 133447.507..133447.507 rows=3D1 loops=3D1)
   -> &= nbsp;Hash Right Join  (cost=3D1816553.69..2535985.56 rows=3D2708 wid= th=3D4) (actual time=3D133405.326..133417.078 rows=3D43906 loops=3D1)
         Hash Cond: (import=5Ferrors.exch= ange=5Fupload=5Fid =3D exchange=5Fuploads.id)
    &nb= sp;    ->  Seq Scan on import=5Ferrors  (cost=3D0.= 00..710802.71 rows=3D2300471 width=3D4) (actual time=3D0.006..19199.569 r= ows=3D2321888 loops=3D1)
         ->= ;  Hash  (cost=3D1816519.84..1816519.84 rows=3D2708 width=3D4) = (actual time=3D112938.606..112938.606 rows=3D43906 loops=3D1)
&= nbsp;              Buckets: 1024  = ;Batches: 1  Memory Usage: 1544kB
      &nb= sp;        ->  Hash Join  (cost=3D28.25.= .1816519.84 rows=3D2708 width=3D4) (actual time=3D42.957..112892.689 rows= =3D43906 loops=3D1)
            &= nbsp;        Hash Cond: (exchange=5Fuploads.upload=5F= destination=5Fid =3D upload=5Fdestinations.id)
    &n= bsp;                ->  I= ndex Scan using index=5Fupload=5Fdestinations=5Fon=5Fcreated=5Fat on exch= ange=5Fuploads  (cost=3D0.00..1804094.96 rows=3D3298545 width=3D12) = (actual time=3D17.686..111649.272 rows=3D3303488 loops=3D1)
&nb= sp;                    =      Index Cond: (created=5Fat >=3D '2012-07-27 21:21:= 57.363944'::timestamp without time zone)
      &= nbsp;              ->  Hash &n= bsp;(cost=3D28.20..28.20 rows=3D4 width=3D8) (actual time=3D0.043..0.043 = rows=3D6 loops=3D1)
            &= nbsp;              Buckets: 1024  = ;Batches: 1  Memory Usage: 1kB
       =                    -&g= t;  Bitmap Heap Scan on upload=5Fdestinations  (cost=3D6.28..28= .20 rows=3D4 width=3D8) (actual time=3D0.026..0.036 rows=3D6 loops=3D1)
                  &= nbsp;              Recheck Cond: (offi= ce=5Fid =3D 6)
             =                    -&g= t;  Bitmap Index Scan on upload=5Fdestinations=5Foffice=5Fid=5Fidx &= nbsp;(cost=3D0.00..6.28 rows=3D4 width=3D0) (actual time=3D0.020..0.020 r= ows=3D6 loops=3D1)
            &n= bsp;                    = ;      Index Cond: (office=5Fid =3D 6)
 Tot= al runtime: 133447.790 ms
(17 rows)

=


The first que= ry shows a cost of = 190,169.55 and runs in 199,806.951 ms. &n= bsp;When I disable nested loop, I get a cost of 2,535,992.34 = which runs in only