X-Original-To: pgsql-performance-postgresql.org@localhost.postgresql.org Received: from localhost (av.hub.org [200.46.204.144]) by postgresql.org (Postfix) with ESMTP id 78D159DCB0C for ; Mon, 28 Nov 2005 22:13:06 -0400 (AST) Received: from postgresql.org ([200.46.204.71]) by localhost (av.hub.org [200.46.204.144]) (amavisd-new, port 10024) with ESMTP id 92272-02 for ; Mon, 28 Nov 2005 22:13:09 -0400 (AST) X-Greylist: from auto-whitelisted by SQLgrey- Received: from relais.videotron.ca (relais.videotron.ca [24.201.245.36]) by postgresql.org (Postfix) with ESMTP id 68A7C9DCAB3 for ; Mon, 28 Nov 2005 22:13:02 -0400 (AST) Received: from [192.168.1.100] ([24.202.23.128]) by VL-MO-MR004.ip.videotron.ca (Sun Java System Messaging Server 6.2-2.05 (built Apr 28 2005)) with ESMTP id <0IQP004MG25U4XB0@VL-MO-MR004.ip.videotron.ca> for pgsql-performance@postgresql.org; Mon, 28 Nov 2005 21:13:07 -0500 (EST) Date: Mon, 28 Nov 2005 21:16:52 -0500 From: David Gagnon Subject: Re: Please help with this explain analyse... In-reply-to: <17298.1133222430@sss.pgh.pa.us> To: Tom Lane Cc: Bricklen Anderson , pgsql-performance@postgresql.org Message-id: <438BBA14.5080103@siunik.com> MIME-version: 1.0 Content-type: text/plain; charset=ISO-8859-1; format=flowed Content-transfer-encoding: 7BIT X-Accept-Language: en-us, en References: <438B958B.3010602@siunik.com> <438B96C6.4090902@PresiNET.com> <17298.1133222430@sss.pgh.pa.us> User-Agent: Mozilla Thunderbird 1.0.7 (Windows/20050923) X-Virus-Scanned: by amavisd-new at hub.org X-Spam-Status: No, score=0.229 required=5 tests=[AWL=0.229] X-Spam-Score: 0.229 X-Spam-Level: X-Archive-Number: 200511/545 X-Sequence-Number: 15802 I restored my db but haven't run the analyse... That was the problem. Thanks /David "Merge Left Join (cost=2273.54..2290.19 rows=228 width=816) (actual time=2098.257..2444.472 rows=8335 loops=1)" " Merge Cond: (("outer".rrnum)::text = "inner"."?column8?")" " -> Merge Join (cost=2131.25..2141.31 rows=228 width=744) (actual time=2037.953..2251.289 rows=8335 loops=1)" " Merge Cond: ("outer"."?column31?" = "inner"."?column77?")" " -> Sort (cost=1975.03..1975.60 rows=228 width=235) (actual time=1798.556..1811.828 rows=8335 loops=1)" " Sort Key: (cr.crrrnum)::text" " -> Hash Join (cost=1451.41..1966.10 rows=228 width=235) (actual time=267.751..515.396 rows=8335 loops=1)" " Hash Cond: ("outer".crnum = "inner".cscrnum)" " -> Seq Scan on cr (cost=0.00..489.77 rows=4529 width=101) (actual time=0.077..97.615 rows=8335 loops=1)" " Filter: (((crypnum)::text = 'M'::text) AND ((crdate + '00:00:00'::interval) <= '2005-01-28 00:00:00'::timestamp without time zone))" " -> Hash (cost=1449.70..1449.70 rows=684 width=134) (actual time=267.568..267.568 rows=13587 loops=1)" " -> Nested Loop (cost=20.59..1449.70 rows=684 width=134) (actual time=33.099..178.524 rows=13587 loops=1)" " -> Seq Scan on gl (cost=0.00..5.21 rows=2 width=91) (actual time=0.021..0.357 rows=1 loops=1)" " Filter: (glsoctrl = 1)" " -> Bitmap Heap Scan on cs (cost=20.59..684.42 rows=3026 width=43) (actual time=33.047..115.151 rows=13587 loops=1)" " Recheck Cond: ((cs.csglnum)::text = ("outer".glnum)::text)" " Filter: ('M'::text = (csypnum)::text)" " -> Bitmap Index Scan on cs_gl_fk (cost=0.00..20.59 rows=3026 width=0) (actual time=32.475..32.475 rows=13587 loops=1)" " Index Cond: ((cs.csglnum)::text = ("outer".glnum)::text)" " -> Sort (cost=156.22..159.65 rows=1372 width=509) (actual time=239.315..254.024 rows=8974 loops=1)" " Sort Key: (rr.rrnum)::text" " -> Seq Scan on rr (cost=0.00..84.72 rows=1372 width=509) (actual time=0.055..33.564 rows=1372 loops=1)" " -> Sort (cost=142.29..144.55 rows=903 width=72) (actual time=60.246..74.813 rows=8932 loops=1)" " Sort Key: (yr.yrref)::text" " -> Bitmap Heap Scan on yr (cost=16.42..97.96 rows=903 width=72) (actual time=8.513..13.587 rows=1154 loops=1)" " Recheck Cond: (((yryotype)::text = 'Client'::text) AND ((yryonum)::text = 'Comptabilite.Recevable.Regroupement'::text))" " -> Bitmap Index Scan on yr_idx1 (cost=0.00..16.42 rows=903 width=0) (actual time=8.471..8.471 rows=1154 loops=1)" " Index Cond: (((yryotype)::text = 'Client'::text) AND ((yryonum)::text = 'Comptabilite.Recevable.Regroupement'::text))" "Total runtime: 2466.197 ms" >Bricklen Anderson writes: > > >>Your loops are what is causing the time spent. >>eg. "actual time=0.127..17.379 rows=1154 loops=8335)" == >>8335*(17.379-0.127)/1000=>143 secs (if my math is correct). >> >> > >As for where the problem is, I think it's the horrid misestimate of the >number of matching rows in cs_pk: > > > >>>" -> Index Scan using cs_pk on cs (cost=0.00..12.83 >>>rows=2 width=144) (actual time=0.087..444.999 rows=13587 loops=1)" >>>" Index Cond: (('M'::text = (cs.csypnum)::text) >>>AND ((cs.csglnum)::text = ("outer".glnum)::text))" >>> >>> > >Has that table been ANALYZEd recently? How about the gl table? > > regards, tom lane > > >