Received: from localhost (maia-2.hub.org [200.46.204.187]) by postgresql.org (Postfix) with ESMTP id DF28E9FB898 for ; Fri, 18 May 2007 07:15:52 -0300 (ADT) Received: from postgresql.org ([200.46.204.71]) by localhost (mx1.hub.org [200.46.204.187]) (amavisd-maia, port 10024) with ESMTP id 46894-01 for ; Fri, 18 May 2007 07:15:45 -0300 (ADT) X-Greylist: delayed 01:12:12.550706 by SQLgrey-1.7.4 Received: from mail.livius.net (mail.livius.net [80.86.96.82]) by postgresql.org (Postfix) with ESMTP id 7C3839FB461 for ; Fri, 18 May 2007 07:15:48 -0300 (ADT) Received: from ilgvaio (86-120-229-138.rdsnet.ro [86.120.229.138] (may be forged)) (authenticated bits=0) by mail.livius.net (8.12.5/8.12.5) with ESMTP id l4IAFheF011883 for ; Fri, 18 May 2007 13:15:43 +0300 From: "Liviu Ionescu" To: Subject: Re: performance drop on 8.2.4, reverting to 8.1.4 Date: Fri, 18 May 2007 13:14:56 +0300 Message-ID: <007501c79935$63072ec0$653e10ac@ilgvaio> MIME-Version: 1.0 Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: quoted-printable X-Priority: 3 (Normal) X-MSMail-Priority: Normal X-Mailer: Microsoft Outlook, Build 10.0.6822 X-MimeOLE: Produced By Microsoft MimeOLE V6.00.2900.3028 Thread-Index: AceZMjA7FQKWItIWR8SnY/XmwJ+vWgAAnRCg In-Reply-To: <20070518094921.GA13598@uio.no> Importance: Normal X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=0.001 tagged_above=0 required=5 tests=BAYES_50=0.001 X-Spam-Level: X-Archive-Number: 200705/314 X-Sequence-Number: 24704 > It will probably be useful with EXPLAIN ANALYZE of your=20 > queries, not just the EXPLAIN. it took 245 seconds to complete, see below. > It looks like the planner thinks this is going to be really=20 > cheap -- so it's misestimating something somewhere. Have you=20 > ANALYZEd recently? yes, but to be sure I did it again before issuing the request; no = improvements... regards, Liviu "Nested Loop Left Join (cost=3D32.03..2026.70 rows=3D1 width=3D125) = (actual time=3D16.686..244822.521 rows=3D2026 loops=3D1)" " Join Filter: (n.nodeid =3D public.nodeattributes.nodeid)" " -> Nested Loop Left Join (cost=3D26.55..1420.57 rows=3D1 = width=3D115) (actual time=3D13.833..176136.527 rows=3D2026 loops=3D1)" " Join Filter: (n.nodeid =3D public.nodeattributes.nodeid)" " -> Nested Loop Left Join (cost=3D21.06..810.90 rows=3D1 = width=3D105) (actual time=3D10.336..95476.175 rows=3D2026 loops=3D1)" " Join Filter: (n.nodeid =3D public.nodeattributes.nodeid)" " -> Nested Loop Left Join (cost=3D15.55..194.15 rows=3D1 = width=3D95) (actual time=3D6.514..11524.892 rows=3D2026 loops=3D1)" " Join Filter: (n.nodeid =3D rtunodes.nodeid)" " -> Nested Loop Left Join (cost=3D11.17..107.94 = rows=3D1 width=3D82) (actual time=3D0.661..71.751 rows=3D2026 = loops=3D1)" " Filter: (templatenodes.nodeid IS NULL)" " -> Hash Left Join (cost=3D11.17..99.66 = rows=3D1 width=3D82) (actual time=3D0.643..36.053 rows=3D2206 = loops=3D1)" " Hash Cond: (n.nodeid =3D = templates.nodeid)" " Filter: (templates.nodeid IS NULL)" " -> Hash Left Join (cost=3D8.73..88.06 = rows=3D2270 width=3D82) (actual time=3D0.502..27.756 rows=3D2270 = loops=3D1)" " Hash Cond: (n.nodeid =3D = rtus.nodeid)" " -> Hash Left Join = (cost=3D4.34..74.11 rows=3D2270 width=3D74) (actual time=3D0.286..20.179 = rows=3D2270 loops=3D1)" " Hash Cond: (n.nodeid =3D = areas.nodeid)" " -> Hash Left Join = (cost=3D1.43..61.83 rows=3D2270 width=3D66) (actual time=3D0.114..13.062 = rows=3D2270 loops=3D1)" " Hash Cond: (n.nodeid = =3D realms.nodeid)" " -> Seq Scan on nodes = n (cost=3D0.00..51.70 rows=3D2270 width=3D49) (actual = time=3D0.016..4.089 rows=3D2270 loops=3D1)" " -> Hash = (cost=3D1.19..1.19 rows=3D19 width=3D17) (actual time=3D0.056..0.056 = rows=3D19 loops=3D1)" " -> Seq Scan on = realms (cost=3D0.00..1.19 rows=3D19 width=3D17) (actual = time=3D0.006..0.023 rows=3D19 loops=3D1)" " -> Hash = (cost=3D1.85..1.85 rows=3D85 width=3D8) (actual time=3D0.156..0.156 = rows=3D85 loops=3D1)" " -> Seq Scan on areas = (cost=3D0.00..1.85 rows=3D85 width=3D8) (actual time=3D0.007..0.070 = rows=3D85 loops=3D1)" " -> Hash (cost=3D3.06..3.06 = rows=3D106 width=3D8) (actual time=3D0.200..0.200 rows=3D106 loops=3D1)" " -> Seq Scan on rtus = (cost=3D0.00..3.06 rows=3D106 width=3D8) (actual time=3D0.010..0.105 = rows=3D106 loops=3D1)" " -> Hash (cost=3D1.64..1.64 rows=3D64 = width=3D4) (actual time=3D0.119..0.119 rows=3D64 loops=3D1)" " -> Seq Scan on templates = (cost=3D0.00..1.64 rows=3D64 width=3D4) (actual time=3D0.006..0.059 = rows=3D64 loops=3D1)" " -> Index Scan using nodeid_pkey on = templatenodes (cost=3D0.00..8.27 rows=3D1 width=3D4) (actual = time=3D0.009..0.009 rows=3D0 loops=3D2206)" " Index Cond: (n.nodeid =3D = templatenodes.nodeid)" " -> Hash Join (cost=3D4.38..63.51 rows=3D1816 = width=3D13) (actual time=3D0.012..4.417 rows=3D1816 loops=3D2026)" " Hash Cond: (rtunodes.rtuid =3D r.nodeid)" " -> Seq Scan on rtunodes (cost=3D0.00..34.16 = rows=3D1816 width=3D9) (actual time=3D0.009..1.290 rows=3D1816 = loops=3D2026)" " -> Hash (cost=3D3.06..3.06 rows=3D106 = width=3D8) (actual time=3D0.194..0.194 rows=3D106 loops=3D1)" " -> Seq Scan on rtus r = (cost=3D0.00..3.06 rows=3D106 width=3D8) (actual time=3D0.005..0.091 = rows=3D106 loops=3D1)" " -> Hash Join (cost=3D5.51..611.90 rows=3D388 = width=3D14) (actual time=3D0.033..39.896 rows=3D2079 loops=3D2026)" " Hash Cond: (a.typeid =3D t.typeid)" " -> Hash Join (cost=3D4.34..604.41 rows=3D647 = width=3D18) (actual time=3D0.031..36.513 rows=3D2079 loops=3D2026)" " Hash Cond: (public.nodeattributes.attributeid = =3D a.attributeid)" " -> Seq Scan on nodeattributes = (cost=3D0.00..505.35 rows=3D23535 width=3D18) (actual = time=3D0.008..16.826 rows=3D23535 loops=3D2026)" " -> Hash (cost=3D4.28..4.28 rows=3D5 = width=3D8) (actual time=3D0.077..0.077 rows=3D5 loops=3D1)" " -> Seq Scan on attributes a = (cost=3D0.00..4.28 rows=3D5 width=3D8) (actual time=3D0.033..0.067 = rows=3D5 loops=3D1)" " Filter: ((name)::text =3D = 'iconName'::text)" " -> Hash (cost=3D1.10..1.10 rows=3D6 width=3D4) = (actual time=3D0.023..0.023 rows=3D6 loops=3D1)" " -> Seq Scan on types t (cost=3D0.00..1.10 = rows=3D6 width=3D4) (actual time=3D0.005..0.012 rows=3D6 loops=3D1)" " Filter: isattributetype" " -> Hash Join (cost=3D5.49..606.76 rows=3D233 width=3D14) = (actual time=3D0.104..38.474 rows=3D1865 loops=3D2026)" " Hash Cond: (a.typeid =3D t.typeid)" " -> Hash Join (cost=3D4.31..601.80 rows=3D388 = width=3D18) (actual time=3D0.101..35.484 rows=3D1865 loops=3D2026)" " Hash Cond: (public.nodeattributes.attributeid =3D = a.attributeid)" " -> Seq Scan on nodeattributes = (cost=3D0.00..505.35 rows=3D23535 width=3D18) (actual = time=3D0.008..16.624 rows=3D23535 loops=3D2026)" " -> Hash (cost=3D4.28..4.28 rows=3D3 width=3D8) = (actual time=3D0.071..0.071 rows=3D3 loops=3D1)" " -> Seq Scan on attributes a = (cost=3D0.00..4.28 rows=3D3 width=3D8) (actual time=3D0.019..0.058 = rows=3D3 loops=3D1)" " Filter: ((name)::text =3D = 'addUPItemplate'::text)" " -> Hash (cost=3D1.10..1.10 rows=3D6 width=3D4) (actual = time=3D0.025..0.025 rows=3D6 loops=3D1)" " -> Seq Scan on types t (cost=3D0.00..1.10 = rows=3D6 width=3D4) (actual time=3D0.004..0.012 rows=3D6 loops=3D1)" " Filter: isattributetype" " -> Hash Join (cost=3D5.48..604.19 rows=3D155 width=3D14) (actual = time=3D0.794..33.783 rows=3D132 loops=3D2026)" " Hash Cond: (a.typeid =3D t.typeid)" " -> Hash Join (cost=3D4.30..600.50 rows=3D259 width=3D18) = (actual time=3D0.791..33.550 rows=3D132 loops=3D2026)" " Hash Cond: (public.nodeattributes.attributeid =3D = a.attributeid)" " -> Seq Scan on nodeattributes (cost=3D0.00..505.35 = rows=3D23535 width=3D18) (actual time=3D0.008..16.623 rows=3D23535 = loops=3D2026)" " -> Hash (cost=3D4.28..4.28 rows=3D2 width=3D8) (actual = time=3D0.060..0.060 rows=3D2 loops=3D1)" " -> Seq Scan on attributes a (cost=3D0.00..4.28 = rows=3D2 width=3D8) (actual time=3D0.015..0.054 rows=3D2 loops=3D1)" " Filter: ((name)::text =3D = 'addUPIsubclass'::text)" " -> Hash (cost=3D1.10..1.10 rows=3D6 width=3D4) (actual = time=3D0.022..0.022 rows=3D6 loops=3D1)" " -> Seq Scan on types t (cost=3D0.00..1.10 rows=3D6 = width=3D4) (actual time=3D0.003..0.009 rows=3D6 loops=3D1)" " Filter: isattributetype" "Total runtime: 244826.065 ms"