Received: from localhost (unknown [200.46.204.183]) by developer.postgresql.org (Postfix) with ESMTP id CAB4E2E0056 for ; Wed, 21 May 2008 07:38:14 -0300 (ADT) Received: from developer.postgresql.org ([200.46.204.71]) by localhost (mx1.hub.org [200.46.204.183]) (amavisd-maia, port 10024) with ESMTP id 08810-04 for ; Wed, 21 May 2008 07:38:05 -0300 (ADT) X-Greylist: from auto-whitelisted by SQLgrey-1.7.6 Received: from yergi.telenet-ops.be (yergi.telenet-ops.be [195.130.132.36]) by developer.postgresql.org (Postfix) with ESMTP id 42F982E003D for ; Wed, 21 May 2008 07:38:05 -0300 (ADT) Received: from harold.telenet-ops.be (unknown [195.130.133.65]) by yergi.telenet-ops.be (Postfix) with ESMTP id C35B95CAA5A for ; Wed, 21 May 2008 12:37:45 +0200 (CEST) Received: from localhost (localhost.localdomain [127.0.0.1]) by harold.telenet-ops.be (Postfix) with SMTP id 51FCA3003B; Wed, 21 May 2008 12:37:24 +0200 (CEST) Received: from mercurius.leuven.smartlounge.be (d5152FE02.access.telenet.be [81.82.254.2]) by harold.telenet-ops.be (Postfix) with ESMTP id 20BDB30009; Wed, 21 May 2008 12:37:24 +0200 (CEST) Received: from kmi.latas.leuven.smartlounge.be (unknown [172.16.20.105]) by mercurius.leuven.smartlounge.be (Postfix) with ESMTP id EDB6B6808A1D; Wed, 21 May 2008 12:37:23 +0200 (CEST) From: Frank Dekervel Organization: Smartlounge To: pgsql-performance@postgresql.org Subject: Re: "append" takes a lot of time in a query Date: Wed, 21 May 2008 12:37:22 +0200 User-Agent: KMail/1.9.9 References: <200805091009.46893.frank.dekervel@smartlounge.be> <13354.1210342366@sss.pgh.pa.us> <200805161759.38066.frank.dekervel@smartlounge.be> In-Reply-To: <200805161759.38066.frank.dekervel@smartlounge.be> MIME-Version: 1.0 Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: 7bit Content-Disposition: inline Message-Id: <200805211237.23178.frank.dekervel@smartlounge.be> X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=0 tagged_above=0 required=5 tests=none X-Spam-Level: X-Archive-Number: 200805/286 X-Sequence-Number: 30254 Hello, Small update on this problem: Wouter Verhelst came to help debugging, and he determined that the 2 seconds were spent planning the query and not executing the query. (executing the query is quick as seen in the query plan). To avoid replanning this query all the time, Wouter suggest replacing the query with a stored procedure (so that the query plan was saved). We did a proof of concept, and it seemed to work very well. Another approach would be caching of prepared statements, but i found no implementations of this on the net. We now still need to find a way to hook the stored procs in our O-R mapper: generating them the first time a query is done (fairly easy), and making "select procname(param1,param2)" behave like a normal query. We tried a stored procedure returning a cursor and this seemed to work, but we'd like to avoid this as, to use cursors, we need to change the core logic of our system that decides whether to use transactions and cursors (now the system does not create a cursor if it does not expect too many rows coming back and so on, and no transaction if no "update" or "insert" queries have to be done). So i'll look further to see if i can make "select foo()" behave exactly like a normal query. Another thing we saw was this: on a project where the query generated a 451-line query plan, the query took 30 milliseconds. On a project where the same query generated a 1051-line query plan (more tables inheriting the "part" table), the query took 2 seconds. Something of exponential complexity in the query planner ? greetings, Frank On Friday 16 May 2008 17:59:37 Frank Dekervel wrote: > Hello, > > Thanks for the explanation. You were right, i misread the query plan. > But the strange thing is this query really takes a long time (see below), > contrary to what the query plan indicates. This makes me believe we are > doing something very wrong... > > xxx => select now(); SELECT * FROM (part LEFT OUTER JOIN part_lang ON > part.id = part_lang.id) WHERE part.parent= 49110; select now(); now > ------------------------------- > 2008-05-16 17:51:15.525056+02 > (1 row) > > parent | id | dirindex | permissions | sequencenumber | partname | lang | > id | online > --------+----+----------+-------------+----------------+----------+------+- >---+-------- (0 rows) > > now > ------------------------------- > 2008-05-16 17:51:17.179043+02 > (1 row) > > As for postgresql inherited tables: we are moving to joined inheritance > already, but we still have a lot of "inherited tables" implementations. It > is the first time we see this kind of problem ... > > I'm the original e-mail for reference. > > thanks already ! > > greetings, > Frank > > On Friday 09 May 2008 16:12:46 Tom Lane wrote: > > Frank Dekervel writes: > > > this turns this query in an append of a whole lot of seq scan/ index > > > scan's. These scans are predictably quick, but the "append" takes 5 > > > seconds (and the numbers of the scans do not add up to the append > > > actual time) > > > > It says 5 milliseconds, not 5 seconds. > > > > > Does someone have an explanation / possible solution for this > > > performance ? > > > > Rethink your schema --- this is pushing the inheritance feature far > > beyond what it's designed to do. > > > > regards, tom lane -- ========================= Frank Dekervel frank.dekervel@smartlounge.be ========================= Smartlounge JP Minckelersstraat 78 3000 Leuven phone:+32 16 311 413 fax:+32 16 311 410 mobile:+32 473 943 421 ========================= http://www.smartlounge.be =========================