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 404379DC9CC for ; Thu, 26 Jan 2006 13:59:52 -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 67934-04 for ; Thu, 26 Jan 2006 13:59:51 -0400 (AST) X-Greylist: from auto-whitelisted by SQLgrey- Received: from exchange.g2switchworks.com (mail.g2switchworks.com [63.87.162.25]) by postgresql.org (Postfix) with ESMTP id 1707C9DC861 for ; Thu, 26 Jan 2006 13:59:49 -0400 (AST) Received: from 10.10.1.37 ([10.10.1.37]) by exchange.g2switchworks.com ([10.10.1.2]) with Microsoft Exchange Server HTTP-DAV ; Thu, 26 Jan 2006 17:59:49 +0000 Received: from state.g2switchworks.com by mail.g2switchworks.com; 26 Jan 2006 11:59:50 -0600 Subject: Re: Incorrect Total runtime Reported by Explain Analyze!? From: Scott Marlowe To: Michael Fuhr Cc: Richard Huxton , Jozsef Szalay , pgsql-performance@postgresql.org In-Reply-To: <20060126175723.GA83137@winnie.fuhr.org> References: <43D8FDB7.10905@archonet.com> <20060126175723.GA83137@winnie.fuhr.org> Content-Type: text/plain Content-Transfer-Encoding: 7bit Message-Id: <1138298389.22740.11.camel@state.g2switchworks.com> Mime-Version: 1.0 X-Mailer: Ximian Evolution 1.4.6 (1.4.6-2) Date: Thu, 26 Jan 2006 11:59:49 -0600 X-Virus-Scanned: by amavisd-new at hub.org X-Spam-Status: No, score=0.297 required=5 tests=[AWL=-0.030, PLING_QUERY=0.326, UNPARSEABLE_RELAY=0.001] X-Spam-Score: 0.297 X-Spam-Level: X-Archive-Number: 200601/449 X-Sequence-Number: 16927 On Thu, 2006-01-26 at 11:57, Michael Fuhr wrote: > On Thu, Jan 26, 2006 at 04:49:59PM +0000, Richard Huxton wrote: > > Jozsef Szalay wrote: > > >I have seen it on occasion that the total runtime reported by explain > > >analyze was much higher than the actual time the query needed to > > >complete. The differences in my case ranged between 20-120 seconds. I'm > > >just curious if anyone else has experienced this and whether there is > > >something that I can do to convince explain analyze to report the > > >execution time of the query itself rather than the time of its own > > >execution. Engine version is 8.1.1. > > > > I think it's down to all the gettime() calls that have to be made to > > measure how long each stage of the query takes. In some cases these can > > take a substantial part of the overall query time. > > Another possibility is that the total query time was indeed that > long because the query was blocked waiting for a lock. For example: Could be, but I've had this happen where the query returned in like 1 second but reported 30 seconds run time.