Received: from maia.hub.org (maia-5.hub.org [200.46.204.29]) by mail.postgresql.org (Postfix) with ESMTP id 66D521337B93 for ; Mon, 15 Nov 2010 04:42:15 -0400 (AST) Received: from mail.postgresql.org ([200.46.204.86]) by maia.hub.org (mx1.hub.org [200.46.204.29]) (amavisd-maia, port 10024) with ESMTP id 29787-03-8 for ; Mon, 15 Nov 2010 08:42:08 +0000 (UTC) X-Greylist: delayed 00:20:28.929718 by SQLgrey-1.7.6 Received: from wentylator.ang.com.pl (wentylator.ang.com.pl [89.174.215.202]) by mail.postgresql.org (Postfix) with ESMTP id 7922B1337BB2 for ; Mon, 15 Nov 2010 04:42:06 -0400 (AST) Received: from Artur7 (cfidsl [83.18.105.226]) by wentylator.ang.com.pl (Postfix) with ESMTP id 9D7A52DD260 for ; Mon, 15 Nov 2010 09:21:36 +0100 (CET) From: =?iso-8859-2?Q?Artur_Zaj=B1c?= To: Subject: Difference between explain analyze and real execution time Date: Mon, 15 Nov 2010 09:21:34 +0100 Message-ID: <000001cb849e$1dce2720$596a7560$@ang.com.pl> MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="----=_NextPart_000_0001_01CB84A6.7F983470" X-Mailer: Microsoft Outlook 14.0 Thread-Index: AcuEnNGVXWIXNqA1T76Mn9kDg4FPTg== Content-Language: pl X-wentylator-MailScanner-Information: Please contact the ISP for more information X-wentylator-MailScanner: Found to be clean X-wentylator-MailScanner-SpamCheck: not spam, SpamAssassin (not cached, score=0, required 6, autolearn=not spam) X-wentylator-MailScanner-From: azajac@ang.com.pl X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=-0.509 tagged_above=-10 required=5 tests=BAYES_05=-0.5, HTML_MESSAGE=0.001, T_RP_MATCHES_RCVD=-0.01 X-Spam-Level: X-Archive-Number: 201011/242 X-Sequence-Number: 41266 This is a multipart message in MIME format. ------=_NextPart_000_0001_01CB84A6.7F983470 Content-Type: text/plain; charset="iso-8859-2" Content-Transfer-Encoding: 7bit I have some simple query (executed with time command): time psql -c 'explain analyze SELECT te.idt FROM t_positions AS te JOIN t_st AS stm ON (te.idt=stm.idt AND 4=stm.idm) WHERE te.idtr IN (347186)' QUERY PLAN ---------------------------------------------------------------------------- ---------------------------------------------------------------------------- Nested Loop (cost=0.00..33.33 rows=2 width=4) (actual time=0.297..0.418 rows=3 loops=1) -> Index Scan using t_positions_index1 on t_positions te (cost=0.00..8.43 rows=3 width=4) (actual time=0.140..0.148 rows=3 loops=1) Index Cond: (idtr = 347186) -> Index Scan using t_st_index4 on t_st stm (cost=0.00..8.29 rows=1 width=4) (actual time=0.078..0.079 rows=1 loops=3) Index Cond: ((stm.idt = te.idt) AND (4 = stm.idm)) Total runtime: 0.710 ms (6 rows) real 0m3.309s user 0m0.002s sys 0m0.002s Why there is so big difference between explain analyze (0.710 ms) and real execution time (3309 ms)? Any suggestions? Psql only execution time: time psql -c 'explain analyze SELECT blabla()' ERROR: function blabla() does not exist real 0m0.011s user 0m0.001s sys 0m0.004s SELECT version(); PostgreSQL 9.0.1 on i686-pc-linux-gnu, compiled by GCC gcc (GCC) 4.1.2 20070502 (Red Hat 4.1.2-12), 32-bit ------------------------------------------- Artur Zajac ------=_NextPart_000_0001_01CB84A6.7F983470 Content-Type: text/html; charset="iso-8859-2" Content-Transfer-Encoding: quoted-printable

I have some simple query (executed with time = command):

time psql =A0-c 'explain analyze SELECT te.idt FROM = t_positions AS te=A0 JOIN t_st AS stm ON (te.idt=3Dstm.idt AND = 4=3Dstm.idm)=A0=A0 WHERE te.idtr IN (347186)'

=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= QUERY PLAN

------------------------------------------------------------= -------------------------------------------------------------------------= -------------------

Nested Loop=A0 (cost=3D0.00..33.33 rows=3D2 width=3D4) = (actual time=3D0.297..0.418 rows=3D3 loops=3D1)

=A0=A0 ->=A0 Index Scan using = t_positions_index1 on t_positions te=A0 (cost=3D0.00..8.43 rows=3D3 = width=3D4) (actual time=3D0.140..0.148 rows=3D3 = loops=3D1)

=A0=A0=A0=A0=A0=A0=A0=A0 Index Cond: (idtr =3D = 347186)

=A0=A0 ->=A0 Index Scan using t_st_index4 on t_st stm=A0 = (cost=3D0.00..8.29 rows=3D1 width=3D4) (actual time=3D0.078..0.079 = rows=3D1 loops=3D3)

=A0=A0=A0=A0=A0=A0=A0=A0 Index Cond: ((stm.idt =3D te.idt) = AND (4 =3D stm.idm))

Total runtime: 0.710 ms

(6 rows)

real=A0=A0=A0 = 0m3.309s

user=A0=A0=A0 0m0.002s

sys=A0=A0=A0=A0 = 0m0.002s

Why there is so big difference between explain analyze = (0.710 ms) and real execution time (3309 ms)? Any = suggestions?

Psql only execution time:

time psql -c 'explain analyze = SELECT blabla()'

ERROR:=A0 function blabla() does not = exist

real=A0=A0=A0 0m0.011s

user=A0=A0=A0 = 0m0.001s

sys=A0=A0=A0=A0 0m0.004s

SELECT = version();

PostgreSQL 9.0.1 on i686-pc-linux-gnu, compiled by GCC gcc = (GCC) 4.1.2 20070502 (Red Hat 4.1.2-12), 32-bit

-------------------------------------------<= /p>

Artur Zajac

------=_NextPart_000_0001_01CB84A6.7F983470--