X-Original-To: pgsql-performance-postgresql.org@localhost.postgresql.org Received: from localhost (unknown [200.46.204.144]) by svr1.postgresql.org (Postfix) with ESMTP id 412BA529E0 for ; Thu, 28 Jul 2005 06:56:03 -0300 (ADT) Received: from svr1.postgresql.org ([200.46.204.71]) by localhost (av.hub.org [200.46.204.144]) (amavisd-new, port 10024) with ESMTP id 02860-03 for ; Thu, 28 Jul 2005 09:55:56 +0000 (GMT) Received: from zproxy.gmail.com (zproxy.gmail.com [64.233.162.199]) by svr1.postgresql.org (Postfix) with ESMTP id 9A57B52889 for ; Thu, 28 Jul 2005 06:55:54 -0300 (ADT) Received: by zproxy.gmail.com with SMTP id z6so202716nzd for ; Thu, 28 Jul 2005 02:55:57 -0700 (PDT) DomainKey-Signature: a=rsa-sha1; q=dns; c=nofws; s=beta; d=gmail.com; h=received:message-id:date:from:reply-to:to:subject:cc:in-reply-to:mime-version:content-type:references; b=dkjgoMwUIRku+QtJaAV2+p+gSttSePVx6tx8DBH/SuKSibIANggYvZuulnkq6LyBs/qP399dTPHVtItQfrxKUO4yANADQVz7AUdLQFUacbYksUyRUpSJomQA4Gf2mB7Jq7JLCapnnj/c8oPuV4ZmwcZi+FWa1lcDDDm5T7oRv0k= Received: by 10.37.22.50 with SMTP id z50mr912833nzi; Thu, 28 Jul 2005 02:55:57 -0700 (PDT) Received: by 10.36.119.19 with HTTP; Thu, 28 Jul 2005 02:55:57 -0700 (PDT) Message-ID: Date: Thu, 28 Jul 2005 15:25:57 +0530 From: Gnanavel S Reply-To: Gnanavel S To: Chris Travers Subject: Re: Left joining against two empty tables makes a query SLOW Cc: pgsql-performance@postgresql.org In-Reply-To: <42E86A03.1070803@travelamericas.com> Mime-Version: 1.0 Content-Type: multipart/alternative; boundary="----=_Part_2293_14846395.1122544557125" References: <42E86A03.1070803@travelamericas.com> X-Virus-Scanned: by amavisd-new at hub.org X-Spam-Status: No, hits=0.488 tagged_above=0 required=5 tests=AWL, HTML_50_60, HTML_MESSAGE, RCVD_BY_IP X-Spam-Level: X-Archive-Number: 200507/434 X-Sequence-Number: 13675 ------=_Part_2293_14846395.1122544557125 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable Content-Disposition: inline On 7/28/05, Chris Travers wrote: >=20 > Hi all; >=20 > I have a customer who currently uses an application which had become > slow. After doing some digging, I found the slow query: >=20 > SELECT c.accno, c.description, c.link, c.category, ac.project_id, > p.projectnumber, > a.department_id, d.description AS department > FROM chart c JOIN acc_trans ac ON (ac.chart_id =3D c.id ) > JOIN ar a ON (a.id =3D ac.trans_id) > LEFT JOIN project p ON (ac.project_id =3D p.id ) > LEFT JOIN department d ON (d.id =3D a.department_id) > WHERE a.customer_id =3D 11373 AND a.id IN ( > SELECT max(id) FROM ar WHERE customer_id =3D 11373 > ); >=20 > (reformatted for readability) >=20 > This is taking 10 seconds to run. >=20 > Interestingly, both the project and department tables are blank, and if > I omit them, the query becomes: > SELECT c.accno, c.description, c.link, c.category, ac.project_id > FROM chart c JOIN acc_trans ac ON (ac.chart_id =3D c.id ) > JOIN ar a ON (a.id =3D ac.trans_id) > WHERE a.customer_id =3D 11373 AND a.id IN ( > SELECT max(id) FROM ar WHERE customer_id =3D 11373 > ); >=20 > This takes 139ms. 1% of the previous query. >=20 > The plan for the long query is: >=20 >=20 > QUERY PLAN >=20 > -------------------------------------------------------------------------= ---------------------------------------------------------------------------= ------------ > Hash IN Join (cost=3D87337.25..106344.93 rows=3D41 width=3D118) (actual > time=3D7615.843..9850.209 rows=3D10 loops=3D1) > Hash Cond: ("outer".trans_id =3D "inner".max) > -> Merge Right Join (cost=3D86620.57..100889.85 rows=3D947598 > width=3D126) (actual time=3D7408.830..9200.435 rows=3D177769 loops=3D1) > Merge Cond: ("outer".id =3D "inner".department_id) > -> Index Scan using department_id_key on department d > (cost=3D0.00..52.66 > rows=3D1060 width=3D36) (actual time=3D0.090..0.090 rows=3D0 loops=3D1) vacuum & reindex the department and project table as the planner expects=20 there are 1060 rows but actually returning nothing. -> Sort (cost=3D86620.57..87067.55 rows=3D178792 width=3D94) > (actual time=3D7408.709..7925.843 rows=3D177769 loops=3D1) > Sort Key: a.department_id > -> Merge Right Join (cost=3D45871.18..46952.83 > rows=3D178792 width=3D94) (actual time=3D4962.122..6671.319 rows=3D177769= loops=3D1) > Merge Cond: ("outer".id =3D "inner".project_id) > -> Index Scan using project_id_key on project p > (cost=3D0.00..49.80 rows=3D800 width=3D36) (actual time=3D0.007..0.007 ro= ws=3D0 > loops=3D1) > -> Sort (cost=3D45871.18..46318.16 rows=3D178792 > width=3D62) (actual time=3D4962.084..5475.636 rows=3D177769 loops=3D1) > Sort Key: ac.project_id > -> Hash Join (cost=3D821.20..13193.43 > rows=3D178792 width=3D62) (actual time=3D174.905..4295.685 rows=3D177769 = loops=3D1) > Hash Cond: ("outer".chart_id =3D "inner".id) > -> Hash Join (cost=3D817.66..10508.02 > rows=3D178791 > width=3D20) (actual time=3D173.952..2840.824 rows=3D177769 loops=3D1) > Hash Cond: ("outer".trans_id =3D > "inner".id) > -> Seq Scan on acc_trans ac > (cost=3D0.00..3304.38 rows=3D181538 width=3D12) (actual time=3D0.062..537= .753 > rows=3D181322 loops=3D1) > -> Hash (cost=3D659.55..659.55 > rows=3D22844 width=3D8) (actual time=3D173.625..173.625 rows=3D0 loops=3D= 1) > -> Seq Scan on ar a > (cost=3D0.00..659.55 rows=3D22844 width=3D8) (actual time=3D0.022..101.82= 8 > rows=3D22844 loops=3D1) > Filter: (customer_id > =3D 11373) > -> Hash (cost=3D3.23..3.23 rows=3D123 > width=3D50) (actual time=3D0.915..0.915 rows=3D0 loops=3D1) > -> Seq Scan on chart c > (cost=3D0.00..3.23 rows=3D123 width=3D50) (actual time=3D0.013..0.528 row= s=3D123 > loops=3D1) > -> Hash (cost=3D716.67..716.67 rows=3D1 width=3D4) (actual > time=3D129.037..129.037 rows=3D0 loops=3D1) > -> Subquery Scan "IN_subquery" (cost=3D716.66..716.67 rows=3D1 > width=3D4) (actual time=3D129.017..129.025 rows=3D1 loops=3D1) > -> Aggregate (cost=3D716.66..716.66 rows=3D1 width=3D4) > (actual time=3D129.008..129.011 rows=3D1 loops=3D1) > -> Seq Scan on ar (cost=3D0.00..659.55 rows=3D22844 > width=3D4) (actual time=3D0.020..73.266 rows=3D22844 loops=3D1) > Filter: (customer_id =3D 11373) > Total runtime: 9954.133 ms > (28 rows) >=20 > The shorter query's plan is: >=20 >=20 > QUERY PLAN >=20 >=20 > -------------------------------------------------------------------------= ---------------------------------------------------------------------------= ----- > Hash Join (cost=3D728.42..732.96 rows=3D8 width=3D50) (actual > time=3D130.908..131.593 rows=3D10 loops=3D1) > Hash Cond: ("outer".id =3D "inner".chart_id) > -> Seq Scan on chart c (cost=3D0.00..3.23 rows=3D123 width=3D50) (actual > time=3D0.006..0.361 rows=3D123 loops=3D1) > -> Hash (cost=3D728.40..728.40 rows=3D8 width=3D8) (actual > time=3D130.841..130.841 rows=3D0 loops=3D1) > -> Nested Loop (cost=3D716.67..728.40 rows=3D8 width=3D8) (actual > time=3D130.692..130.805 rows=3D10 loops=3D1) > -> Nested Loop (cost=3D716.67..720.89 rows=3D1 width=3D8) > (actual time=3D130.626..130.639 rows=3D1 loops=3D1) > -> HashAggregate (cost=3D716.67..716.67 rows=3D1 > width=3D4) (actual time=3D130.484..130.487 rows=3D1 loops=3D1) > -> Subquery Scan "IN_subquery" > (cost=3D716.66..716.67 rows=3D1 width=3D4) (actual time=3D130.455..130.46= 4 > rows=3D1 loops=3D1) > -> Aggregate (cost=3D716.66..716.66 > rows=3D1 width=3D4) (actual time=3D130.445..130.448 rows=3D1 loops=3D1) > -> Seq Scan on ar > (cost=3D0.00..659.55 rows=3D22844 width=3D4) (actual time=3D0.020..74.174 > rows=3D22844 loops=3D1) > Filter: (customer_id =3D 11373) > -> Index Scan using ar_id_key on ar a > (cost=3D0.00..4.20 rows=3D1 width=3D4) (actual time=3D0.122..0.125 rows= =3D1 loops=3D1) > Index Cond: (a.id =3D "outer".max) > Filter: (customer_id =3D 11373) > -> Index Scan using acc_trans_trans_id_key on acc_trans > ac (cost=3D0.00..7.41 rows=3D8 width=3D12) (actual time=3D0.051..0.097 ro= ws=3D10 > loops=3D1) > Index Cond: ("outer".max =3D ac.trans_id) > Total runtime: 131.879 ms > (17 rows) >=20 > I am not sure if I want to remove support for the other two tables > yet. However, I wanted to submit this here as a (possibly corner-) > case where the plan seems to be far slower than it needs to be. >=20 > Best Wishes, > Chris Travers > Metatron Technology Consulting >=20 > ---------------------------(end of broadcast)--------------------------- > TIP 6: explain analyze is your friend >=20 --=20 with regards, S.Gnanavel Satyam Computer Services Ltd. ------=_Part_2293_14846395.1122544557125 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable Content-Disposition: inline

On 7/28/05, Chris Travers <c= hris@travelamericas.com> wrote:
Hi all;

I have a customer who currently uses an application which ha= d become
slow.  After doing some digging, I found the slow que= ry:

SELECT c.accno, c.description, c.link, c.category, ac.project_id= ,
p.projectnumber ,
        a.department_id, d.des= cription AS department
FROM chart c JOIN acc_trans ac ON (ac.chart_id = =3D c.id)
     &nbs= p;  JOIN ar a ON (a.id =3D ac.trans_i= d)
        LEFT JOIN project p O= N ( ac.project_id =3D p.id)
   &n= bsp;    LEFT JOIN department d ON (d.id =3D a.department_id)
WHERE a.customer_id =3D 11373 AND a.id IN (
      &n= bsp; SELECT max(id) FROM ar WHERE customer_id =3D 11373
);

(reformatted for readability)

This is taking 10 second= s to run.

Interestingly, both the project and department tables are = blank, and if
I omit them, the query becomes:
SELECT c.accno, c.descr= iption , c.link, c.category, ac.project_id
FROM chart c JOIN acc_trans ac ON (a= c.chart_id =3D c.id)
    = ;    JOIN ar a ON (a.id =3D= ac.trans_id)
WHERE a.customer_id =3D 11373 AND=20 a.id IN (
     &nbs= p;  SELECT max(id) FROM ar WHERE customer_id =3D 11373
);
<= br>This takes 139ms.  1% of the previous query.

The plan f= or the long query is:


QUERY PLAN
----------------------------= ---------------------------------------------------------------------------= ---------------------------------------------------------
Hash IN Join  (cost=3D87337.25..106344.93 rows=3D41 width=3D= 118) (actual
time=3D7615.843..9850.209 rows=3D10 loops=3D1)
 &nb= sp; Hash Cond: ("outer".trans_id =3D "inner".max)
&n= bsp;  ->  Merge Right Join  (cost=3D 86620.57..100889.85 rows=3D947598
width=3D126) (actual time=3D7408.830..= 9200.435 rows=3D177769 loops=3D1)
      &n= bsp;  Merge Cond: ("outer".id =3D "inner".departme= nt_id)
         ->  = ;Index Scan using department_id_key on department d
(cost=3D0.00..52.66
rows=3D1060 width=3D36) (actual time=3D0.090..0.= 090 rows=3D0 loops=3D1)

vacuum & reindex the department and project table as the planner expect= s there are 1060 rows but actually returning nothing.

 &= nbsp;       ->  Sort  = (cost=3D86620.57..87067.55 rows=3D178792 width=3D94)
(actual time=3D 7408.709..7925.843 rows=3D177769 loops=3D1)
    &nbs= p;          Sort Key: a.depart= ment_id
          &nbs= p;    ->  Merge Right Join  (cost=3D45871.18..46952.83
= rows=3D178792 width=3D94) (actual time=3D4962.122..6671.319 rows=3D177769 l= oops=3D1)
          &n= bsp;          Merge Cond: ("outer".id =3D "inner".project_id)
&nbs= p;            &= nbsp;       ->  Index Scan using project_id_key on project p
(cost=3D0.= 00..49.80 rows=3D800 width=3D36) (actual time=3D0.007..0.007 rows=3D0
lo= ops=3D1)
          &nb= sp;          ->  Sort  (cost=3D45871.18..46318.16 rows=3D178792width=3D62) (actual time=3D4962.084..5475.636 rows=3D177769 loops=3D1)            &n= bsp;            = ;  Sort Key: ac.project_id
        =             &nb= sp;      ->  Hash Join  (cost=3D821.20..13193.43
rows=3D17= 8792 width=3D62) (actual time=3D174.905..4295.685 rows=3D177769 loops=3D1)<= br>            =             &nb= sp;        Hash Cond: ("outer".chart_id =3D "inner".id)
 &= nbsp;           &nbs= p;            &= nbsp;      ->  Hash Join  (cost=3D817.66..10508.02
rows=3D17= 8791
width=3D20) (actual time=3D173.952..2840.824 rows=3D177769 loops=3D= 1)
           &nb= sp;            =             &nb= sp;  Hash Cond: ("outer".trans_id =3D
"inner".id)
&nbs= p;            &= nbsp;           &nbs= p;             ->  Seq Scan on acc_trans ac
(cost=3D0.00..3304.38 rows=3D1= 81538 width=3D12) (actual time=3D0.062..537.753
rows=3D181322 loops=3D1)=
            = ;            &n= bsp;            = ;  ->  Hash  (cost=3D659.55..659.55
rows=3D22844 wid= th=3D8) (actual time=3D173.625..173.625 rows=3D0 loops=3D1)
  =             &nb= sp;            =             &nb= sp;     ->  Seq Scan on ar a
(cost=3D0.00..659.55 rows=3D22844 widt= h=3D8) (actual time=3D0.022..101.828
rows=3D22844 loops=3D1)
 &n= bsp;            = ;            &n= bsp;            = ;            Filter: (customer_id
=3D 11373)
      &= nbsp;           &nbs= p;            &= nbsp; ->  Hash  (cost=3D3.23..3.23 rows=3D123
width=3D5= 0) (actual time=3D0.915..0.915 rows=3D0 loops=3D1)
   &nb= sp;            =             &nb= sp;          ->  Seq Scan on chart c
(cost=3D0.00..3.23 rows=3D123 width= =3D50) (actual time=3D0.013..0.528 rows=3D123
loops=3D1)
  = ->  Hash  (cost=3D716.67..716.67 rows=3D1 width=3D4= ) (actual
time=3D129.037..129.037 rows=3D0 loops=3D1)
         ->  Subquery Scan "IN_subquery"  (cost=3D716.66..716.67 rows=3D1
width= =3D4) (actual time=3D129.017..129.025 rows=3D1 loops=3D1)
  &n= bsp;            ->  Aggregate  (cost=3D716.66..716.66 rows=3D1 width=3D4)
(actual time=3D129.008..129.011 rows=3D1 loops=3D1)
 =             &nb= sp;       ->  Seq Scan on ar  (cost=3D0.00..659.55 rows=3D2284= 4
width=3D4) (actual time=3D0.020..73.266 rows=3D22844 loops=3D1)
&nb= sp;            =             &nb= sp; Filter: (customer_id =3D 11373)
Total runtime: 9954.133 ms
(28 rows)=

The shorter query's plan is:


QUERY PLAN

---------= ---------------------------------------------------------------------------= ---------------------------------------------------------------------
Hash Join  (cost=3D728.42..732.96 rows=3D8 width=3D50) (actu= al
time=3D130.908..131.593 rows=3D10 loops=3D1)
   Hash Con= d: ("outer".id =3D "inner".chart_id)
   -&= gt;  Seq Scan on chart c  (cost=3D0.00..3.23 rows=3D123 width=3D50) (actual
time=3D0.006..0.361 rows=3D123 loops=3D1= )
   ->  Hash  (cost=3D728.40..728.40 r= ows=3D8 width=3D8) (actual
time=3D130.841..130.841 rows=3D0 loops=3D1)         ->  Nested Loop  (cost=3D716.67..728.40 rows=3D8 width=3D8) (actual
time=3D130.692..130.805 rows=3D10 loops=3D1)
 = ;            &n= bsp; ->  Nested Loop  (cost=3D716.67..720.89 rows=3D1 width=3D8)
(actual time=3D130.626..130.639 rows=3D1 loops=3D1)
 =             &nb= sp;       ->  HashAggregate  (cost=3D716.67..716.67 rows=3D1width=3D4) (actual time=3D130.484..130.487 rows=3D1 loops=3D1)
 &= nbsp;           &nbs= p;             ->  Subquery Scan "IN_subquery"
(cost=3D716.66..7= 16.67 rows=3D1 width=3D4) (actual time=3D130.455..130.464
rows=3D1 loops= =3D1)
           =             &nb= sp;         ->  Aggregate  (cost=3D716.66..716.66
rows=3D1 wi= dth=3D4) (actual time=3D130.445..130.448 rows=3D1 loops=3D1)
  = ;            &n= bsp;            = ;            ->  Seq Scan on ar
(cost=3D0.00..659.55 rows=3D22844 width= =3D4) (actual time=3D0.020..74.174
rows=3D22844 loops=3D1)
 &nbs= p;            &= nbsp;           &nbs= p;            &= nbsp;     Filter: (customer_id =3D 11373)
      &nbs= p;            &= nbsp; ->  Index Scan using ar_id_key on ar a
(cost=3D0.00..4.20 r= ows=3D1 width=3D4) (actual time=3D0.122..0.125 rows=3D1 loops=3D1)
 = ;            &n= bsp;            = ; Index Cond: (a.id =3D "outer".max)            &n= bsp;            = ;  Filter: (customer_id =3D 11373)
      &nbs= p;        ->  Index Scan using acc_trans_trans_id_key on acc_trans
ac=   (cost=3D0.00..7.41 rows=3D8 width=3D12) (actual time=3D0.051..0= .097 rows=3D10
loops=3D1)
       &= nbsp;           &nbs= p; Index Cond: ("outer".max =3D ac.trans_id)
Total runtime: 131.= 879 ms
(17 rows)

I am not sure if I want to remove support for th= e other two tables
yet.   However, I wanted to submit this her= e as a (possibly corner-)
case where the plan seems to be far slower than it needs to be.

= Best Wishes,
Chris Travers
Metatron Technology Consulting

----= -----------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend



--
with regards,
S.Gnanavel
Satyam Computer Services= Ltd. ------=_Part_2293_14846395.1122544557125--