Received: from localhost (maia-5.hub.org [200.46.204.182]) by postgresql.org (Postfix) with ESMTP id A88389F9A3E; Wed, 29 Aug 2007 07:16:00 -0300 (ADT) Received: from postgresql.org ([200.46.204.71]) by localhost (mx1.hub.org [200.46.204.182]) (amavisd-maia, port 10024) with ESMTP id 65166-01; Wed, 29 Aug 2007 07:15:45 -0300 (ADT) X-Greylist: from auto-whitelisted by SQLgrey-1.7.5 X-Greylist: from auto-whitelisted by SQLgrey-1.7.5 Received: from gamma.m.infra.net (mail2.infra.net [212.89.96.7]) by postgresql.org (Postfix) with ESMTP id 982519F9A3D; Wed, 29 Aug 2007 07:15:53 -0300 (ADT) Received: from epsilon.m.infra.net (epsilon.m.infra.net [212.89.96.8]) by gamma.m.infra.net (8.13.4/8.13.4/Debian-3sarge3) with ESMTP id l7TAFo9G012966; Wed, 29 Aug 2007 12:15:50 +0200 Received: from EL184 ([213.23.198.206]) (authenticated bits=0) by epsilon.m.infra.net (8.13.4/8.13.4/Debian-3) with ESMTP id l7TAFn2I004095 (version=TLSv1/SSLv3 cipher=RC4-MD5 bits=128 verify=NOT); Wed, 29 Aug 2007 12:15:50 +0200 From: "Jens Reufsteck" To: , Subject: Performance issue with nested loop Date: Wed, 29 Aug 2007 12:15:49 +0200 Message-ID: <009501c7ea25$92d60ea0$8c01a8c0@hobsons.loc> MIME-Version: 1.0 Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable X-Mailer: Microsoft Office Outlook 11 Thread-Index: AcfpbBgiCDNzvEaoRDOHDy7PmlNg9g== X-MimeOLE: Produced By Microsoft MimeOLE V6.00.2900.3138 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: 200708/1883 X-Sequence-Number: 119732 Hi all, I'm having a strange performance issue with two almost similar queries, = the one running as expected, the other one taking far more time. The only difference is that I have "uniid in (10)" in the normally running query = and "uniid in (9,10)" in the other one. The number of rows resulting from = the respective table differs not very much being 406 for the first and 511 = for the second query. This is the full query - the "uniid in (9,10)" is in the last subquery: SELECT 'Anzahl' AS column1, count(DISTINCT sid) AS column2 FROM ( SELECT sid FROM stud WHERE stud.status > 0 AND length(stud.vname) > 1 AND length(stud.nname) > 1 ) AS qur_filter_1 INNER JOIN ( SELECT DISTINCT sid FROM stud_vera INNER JOIN phon USING (sid) WHERE veraid =3D 22 AND stud_vera.status > 0 AND ( ( veraid IN (2, 3, 22, 24, 36) AND phontyp =3D 5 AND phon.typ =3D 1 AND phon.status > 0 ) OR ( veraid NOT IN (2, 3, 22, 24, 36) ) ) ) AS qur_filter_2 USING (sid) INNER JOIN ( SELECT DISTINCT sid=20 FROM ausb INNER JOIN uni USING (uniid) WHERE uni.uniort IN ('Augsburg') AND ausb.overview =3D 1 AND ausb.zweitstudium !=3D 2 AND ausb.status > 0 ) AS qur_filter_3 USING (sid) INNER JOIN ( SELECT DISTINCT sid=20 FROM ausb WHERE uniid IN (9, 10) AND ausb.overview =3D 1 AND ausb.zweitstudium !=3D 2 AND ausb.status > 0 ) AS qur_filter_4 USING (sid) These are the query-plans for both queries, first the problematic one: Aggregate (cost=3D78785.78..78785.79 rows=3D1 width=3D4) (actual time=3D698777.890..698777.891 rows=3D1 loops=3D1) -> Nested Loop (cost=3D65462.58..78785.78 rows=3D1 width=3D4) = (actual time=3D6743.856..698776.957 rows=3D250 loops=3D1) Join Filter: ("outer".sid =3D "inner".sid) -> Merge Join (cost=3D11031.79..11883.12 rows=3D1 width=3D12) = (actual time=3D387.837..433.612 rows=3D494 loops=3D1) Merge Cond: ("outer".sid =3D "inner".sid) -> Nested Loop (cost=3D5643.11..6490.17 rows=3D19 = width=3D8) (actual time=3D114.323..154.043 rows=3D494 loops=3D1) -> Unique (cost=3D5643.11..5645.35 rows=3D180 = width=3D4) (actual time=3D114.202..116.002 rows=3D511 loops=3D1) -> Sort (cost=3D5643.11..5644.23 rows=3D448 = width=3D4) (actual time=3D114.199..114.717 rows=3D511 loops=3D1) Sort Key: public.ausb.sid -> Seq Scan on ausb = (cost=3D0.00..5623.38 rows=3D448 width=3D4) (actual time=3D0.351..112.459 rows=3D511 = loops=3D1) Filter: (((uniid =3D 9) OR (uniid = =3D 10)) AND (overview =3D 1) AND (zweitstudium <> 2) AND (status > 0)) -> Index Scan using stud_pkey on stud = (cost=3D0.00..4.67 rows=3D1 width=3D4) (actual time=3D0.062..0.067 rows=3D1 loops=3D511) Index Cond: (stud.sid =3D "outer".sid) Filter: ((status > 0) AND = (length((vname)::text) > 1) AND (length((nname)::text) > 1)) -> Materialize (cost=3D5388.68..5392.05 rows=3D337 = width=3D4) (actual time=3D273.506..276.785 rows=3D511 loops=3D1) -> Unique (cost=3D5383.29..5384.98 rows=3D337 = width=3D4) (actual time=3D273.501..275.421 rows=3D511 loops=3D1) -> Sort (cost=3D5383.29..5384.13 rows=3D337 = width=3D4) (actual time=3D273.499..274.091 rows=3D511 loops=3D1) Sort Key: public.ausb.sid -> Hash Join (cost=3D17.61..5369.14 = rows=3D337 width=3D4) (actual time=3D1.139..272.465 rows=3D511 loops=3D1) Hash Cond: ("outer".uniid =3D "inner".uniid) -> Seq Scan on ausb (cost=3D0.00..4827.30 rows=3D104174 width=3D8) (actual = time=3D0.026..200.111 rows=3D103593 loops=3D1) Filter: ((overview =3D 1) = AND (zweitstudium <> 2) AND (status > 0)) -> Hash (cost=3D17.60..17.60 = rows=3D2 width=3D4) (actual time=3D0.435..0.435 rows=3D2 loops=3D1) -> Seq Scan on uni (cost=3D0.00..17.60 rows=3D2 width=3D4) (actual time=3D0.412..0.424 = rows=3D2 loops=3D1) Filter: = ((uniort)::text =3D 'Augsburg'::text) -> Unique (cost=3D54430.79..66664.18 rows=3D10599 width=3D4) = (actual time=3D6.851..1374.135 rows=3D40230 loops=3D494) -> Merge Join (cost=3D54430.79..66319.65 rows=3D137811 = width=3D4) (actual time=3D6.849..1282.333 rows=3D40233 loops=3D494) Merge Cond: ("outer".sid =3D "inner".sid) Join Filter: (((("outer".veraid =3D 2) OR = ("outer".veraid =3D 3) OR ("outer".veraid =3D 22) OR ("outer".veraid =3D 24) OR = ("outer".veraid =3D 36)) AND ("inner".phontyp =3D 5) AND ("inner".typ =3D 1) AND = ("inner".status > 0)) OR (("outer".veraid <> 2) AND ("outer".veraid <> 3) AND = ("outer".veraid <> 22) AND ("outer".veraid <> 24) AND ("outer".veraid <> 36))) -> Sort (cost=3D11962.11..12098.59 rows=3D54593 = width=3D8) (actual time=3D0.547..46.482 rows=3D53354 loops=3D494) Sort Key: stud_vera.sid -> Bitmap Heap Scan on stud_vera (cost=3D2239.14..7666.61 rows=3D54593 width=3D8) (actual = time=3D43.096..165.300 rows=3D53354 loops=3D1) Recheck Cond: (veraid =3D 22) Filter: (status > 0) -> Bitmap Index Scan on stud_vera_sid_veraid_idx (cost=3D0.00..2239.14 rows=3D58765 width=3D0) = (actual time=3D41.242..41.242 rows=3D61855 loops=3D1) Index Cond: (veraid =3D 22) -> Sort (cost=3D42468.68..43407.53 rows=3D375539 = width=3D12) (actual time=3D6.297..533.711 rows=3D375539 loops=3D494) Sort Key: phon.sid -> Seq Scan on phon (cost=3D0.00..7696.39 rows=3D375539 width=3D12) (actual time=3D0.048..544.999 rows=3D375539 = loops=3D1) !!!! The query-plan for the normally running query: !!!!! Aggregate (cost=3D77846.97..77846.98 rows=3D1 width=3D4) (actual time=3D5488.913..5488.913 rows=3D1 loops=3D1) -> Nested Loop (cost=3D65471.70..77846.97 rows=3D1 width=3D4) = (actual time=3D3913.839..5488.513 rows=3D208 loops=3D1) Join Filter: ("outer".sid =3D "inner".sid) -> Merge Join (cost=3D60088.41..72454.41 rows=3D1 width=3D12) = (actual time=3D3598.105..4841.242 rows=3D208 loops=3D1) Merge Cond: ("outer".sid =3D "inner".sid) -> Unique (cost=3D54430.79..66664.18 rows=3D10599 = width=3D4) (actual time=3D3479.029..4697.051 rows=3D40129 loops=3D1) -> Merge Join (cost=3D54430.79..66319.65 = rows=3D137811 width=3D4) (actual time=3D3479.027..4616.245 rows=3D40132 loops=3D1) Merge Cond: ("outer".sid =3D "inner".sid) Join Filter: (((("outer".veraid =3D 2) OR ("outer".veraid =3D 3) OR ("outer".veraid =3D 22) OR ("outer".veraid =3D = 24) OR ("outer".veraid =3D 36)) AND ("inner".phontyp =3D 5) AND ("inner".typ = =3D 1) AND ("inner".status > 0)) OR (("outer".veraid <> 2) AND ("outer".veraid <> = 3) AND ("outer".veraid <> 22) AND ("outer".veraid <> 24) AND = ("outer".veraid <> 36))) -> Sort (cost=3D11962.11..12098.59 = rows=3D54593 width=3D8) (actual time=3D274.248..315.052 rows=3D53252 loops=3D1) Sort Key: stud_vera.sid -> Bitmap Heap Scan on stud_vera (cost=3D2239.14..7666.61 rows=3D54593 width=3D8) (actual = time=3D46.669..167.599 rows=3D53352 loops=3D1) Recheck Cond: (veraid =3D 22) Filter: (status > 0) -> Bitmap Index Scan on stud_vera_sid_veraid_idx (cost=3D0.00..2239.14 rows=3D58765 width=3D0) = (actual time=3D44.618..44.618 rows=3D61857 loops=3D1) Index Cond: (veraid =3D 22) -> Sort (cost=3D42468.68..43407.53 = rows=3D375539 width=3D12) (actual time=3D3204.729..3681.598 rows=3D375090 loops=3D1) Sort Key: phon.sid -> Seq Scan on phon = (cost=3D0.00..7696.39 rows=3D375539 width=3D12) (actual time=3D0.052..628.838 rows=3D375539 = loops=3D1) -> Materialize (cost=3D5657.62..5657.71 rows=3D9 = width=3D8) (actual time=3D91.290..105.557 rows=3D406 loops=3D1) -> Nested Loop (cost=3D5234.08..5657.61 rows=3D9 = width=3D8) (actual time=3D91.282..104.571 rows=3D406 loops=3D1) -> Unique (cost=3D5234.08..5235.20 rows=3D90 width=3D4) (actual time=3D91.156..92.232 rows=3D420 loops=3D1) -> Sort (cost=3D5234.08..5234.64 = rows=3D224 width=3D4) (actual time=3D91.154..91.484 rows=3D420 loops=3D1) Sort Key: public.ausb.sid -> Seq Scan on ausb (cost=3D0.00..5225.34 rows=3D224 width=3D4) (actual time=3D0.266..90.242 = rows=3D420 loops=3D1) Filter: ((uniid =3D 10) AND (overview =3D 1) AND (zweitstudium <> 2) AND (status > 0)) -> Index Scan using stud_pkey on stud (cost=3D0.00..4.67 rows=3D1 width=3D4) (actual time=3D0.024..0.026 = rows=3D1 loops=3D420) Index Cond: (stud.sid =3D "outer".sid) Filter: ((status > 0) AND (length((vname)::text) > 1) AND (length((nname)::text) > 1)) -> Unique (cost=3D5383.29..5384.98 rows=3D337 width=3D4) = (actual time=3D1.520..2.686 rows=3D511 loops=3D208) -> Sort (cost=3D5383.29..5384.13 rows=3D337 width=3D4) = (actual time=3D1.519..1.871 rows=3D511 loops=3D208) Sort Key: public.ausb.sid -> Hash Join (cost=3D17.61..5369.14 rows=3D337 = width=3D4) (actual time=3D1.133..314.584 rows=3D511 loops=3D1) Hash Cond: ("outer".uniid =3D "inner".uniid) -> Seq Scan on ausb (cost=3D0.00..4827.30 rows=3D104174 width=3D8) (actual time=3D0.030..226.532 rows=3D103593 = loops=3D1) Filter: ((overview =3D 1) AND = (zweitstudium <> 2) AND (status > 0)) -> Hash (cost=3D17.60..17.60 rows=3D2 = width=3D4) (actual time=3D0.392..0.392 rows=3D2 loops=3D1) -> Seq Scan on uni (cost=3D0.00..17.60 rows=3D2 width=3D4) (actual time=3D0.369..0.381 rows=3D2 loops=3D1) Filter: ((uniort)::text =3D 'Augsburg'::text) The estimated row numbers are not bad as long as one table is affected. They're much worse as soon as two or more tables are joined. Though the query plans are slightly different, the number of merged rows at = different stages seems to be rather the same for both plans. The big difference in = my eyes seems the cost for the first nested loop. This seems to be the = point, where the long running query consumes most time. I've then set enable_nestloop to off, and actually the problem disappears.=20 Other maybe relevant parameters: default_statistics_target =3D 100 work_mem =3D 4096 max_fsm_pages =3D 100000 My questions: What could be the problem behind high amount of actually used time for = the nested loop in the first query? If we decided to constantly turn off nested loops, what side effects = would we have to expect? Are there more granular ways to tell the query planner when to use = nested loops? Or just other ideas what to do? We'd be grateful for any hint! Many thanks Jens --=20 Jens Reufsteck Hobsons GmbH Wildunger Stra=DFe 6 60487 Frankfurt am Main Deutschland Tel: +49 (69) 255 37-140 Fax: +49 (69) 255 37-2140 http://www.hobsons.de http://www.hobsons.ch Gesch=E4ftsf=FChrung: Christopher Letcher, Judith Oppitz, Adam Webster Amtsgericht Frankfurt HRB 58610