From: Achilleas Mantzios <achill@matrix.gatewaynet.com>
Organization: Dynacom Tankers Mgmt
To: pgsql-admin@postgresql.org
Subject: Re: Postgresql 9.0.2 explain analyze very slow (10x),
	compared to actual query time
Date: Wed, 12 Jan 2011 13:18:43 +0200
User-Agent: KMail/1.9.7
References: <201101111753.22602.achill@matrix.gatewaynet.com>
	<18991.1294762751@sss.pgh.pa.us>
In-Reply-To: <18991.1294762751@sss.pgh.pa.us>
MIME-Version: 1.0
Content-Type: text/plain;
  charset="iso-8859-7"
Content-Transfer-Encoding: quoted-printable
Content-Disposition: inline
Message-Id: <201101121318.44007.achill@matrix.gatewaynet.com>

=D3=F4=E9=F2 Tuesday 11 January 2011 18:19:11 =EF/=E7 Tom Lane =DD=E3=F1=E1=
=F8=E5:
> Achilleas Mantzios <achill@matrix.gatewaynet.com> writes:
> > I have noticed that in 9.0.2 EXPLAIN ANALYZE takes considerably longer =
time to return than the actual query. I never noticed this in 8.3.
>=20
> Same hardware?  What it sounds like is you're running 9.0 on a machine
> with slow gettimeofday().
>=20

It is on a different hardware. I have three setups here, i have written a s=
mall program to assess gettimeofday.
My setups are as follows
1) Prod machine (thereafter called LINUX_PROD) :
System:	Linux Suse 2.6.16.46-0.12-smp, 16 x Intel Xeon(R) X7350 @ 2.93GHz, =
64GB memory
DB: PostgreSQL 8.3.13, shared_buffers=3D16GB, work_mem=3D512MB, db size=3D9=
4GB
2) Dev machine (therafter called FBSD_DEV) :
System : FreeBSD 6.3, Intel(R) Core(TM)2 Duo CPU @ 2.80GHz, 2GB memory
DB: PostgreSQL 8.3.13, shared_buffers=3D512MB, work_mem=3D1MB, db size=3D76=
GB
3) Test machine (thereafter called FBSD_TEST) :
System: FreeBSD 8.1, 4 x AMD Phenom(tm) 965 @ 3.4 GHz, 8GB memory
DB: PostgreSQL 9.0.2, shared_buffers=3D5GB, work_mem=3D512MB, db size=3D7GB

The FBSD_TEST system,  in the majority of cases seems to outperform LINUX_P=
ROD
(rough impression watching execution times of my app, random benchmarks, no=
thing too detailed, but it is still a very fast system,
and i have been testing for over 2 months with this new system, testing 9.0=
=2E2 performance, etc..)
However i found two issues with FBSD_TEST: The EXPLAIN ANALYZE performance,=
 and one specific query
which runs considerably slower in FBSD_TEST than both LINUX_PROD and FBSD_D=
EV.
Regarding gettimeofday (2), i wrote this program :
#include <stdio.h>
#include <stdlib.h>
#include <sys/time.h>
int main(int argc,char** argv) {
        struct timeval *tp=3Dcalloc(1,sizeof(struct timeval));
        int runna;
        for (runna=3D0;runna<1000000;runna++) {
                int rc=3Dgettimeofday(tp,NULL);
                long micros =3D tp->tv_sec * 1000000 + tp->tv_usec;
                printf("cur_time=3D%u micro secs\n",micros);
        }
}

=46or some reason, LINUX_PROD runs this program much much faster than the t=
wo FBDs (FBSD_DEV, FBSD_PROD)
I get these values for=20
% time ./gettimeofday_test > /dev/null
LINUX_PROD real=3D0m0.373s, user=3D0m0.364s, sys=3D0m0.004s
=46BSD_DEV real=3D4.29s, user=3D0.526s, sys=3D3.764s
=46BSD_TEST real=3D1.66s, user=3D0.260s, sys=3D1.407s

So at least regarding gettimeofday, and setting linux aside, the slower fbs=
d (FBSD_DEV) seems considerably slower
than the faster fbsd (FBSD_TEST).

However for the query:

SELECT distinct m.id,coalesce(m.givenname,''),coalesce(m.midname,''),m.surn=
ame from marinerstates ms,vessels vsl,mariner m=20
where m.id=3Dms.marinerid and ms.vslid=3Dvsl.id and ms.state=3D'Active' and=
 coalesce(ms.endtime,now())::date >=3D '2006-07-15' and=20
ms.starttime::date <=3D '2007-01-11'  and m.marinertype=3D'Mariner'  and m.=
id not in=20
(SELECT distinct mold.id from marinerstates msold,vessels vslold,mariner mo=
ld  where mold.id=3Dmsold.marinerid and msold.vslid=3Dvslold.id and=20
msold.state=3D'Active' and coalesce(msold.endtime,now())::date >=3D '2006-0=
7-15' and msold.starttime::date <=3D '2007-01-11' and exists=20
(select 1 from marinerstates msold2 where msold2.marinerid=3Dmsold.marineri=
d and msold2.state=3D'Active' and msold2.id <> msold.id and=20
msold2.starttime<msold.starttime AND (msold.starttime-msold2.endtime)<=3D'1=
8 months')  and mold.marinertype=3D'Mariner' )=20
order by m.surname,coalesce(m.givenname,''),coalesce(m.midname,'');  =20
with the EXPLAIN ANALYZE version

i get the following execution times: (with \timing) (note however that FBSD=
_DEV has a considerably smaller database, the other two are compareable)
=46BSD_DEV : query : 240,419 ms, EXPLAIN ANALYZE query : Total runtime: 538=
=2E468 ms
LINUX_PROD : query : 219.568 ms, EXPLAIN ANALYZE query : Total runtime: 216=
=2E926 ms
=46BSD_TEST : query : 2587,465 ms, EPXLAIN ANALYZE query : Total runtime: 9=
3711.648 ms
The last numbers seem huge.

Up to now this query was the first operation in which i witnessed FBSD_TEST=
 to be actually slower than LINUX_PROD,
but that could be my fault as a DBA, haven't looked much into EXPLAIN yet.
However the performance of EXPLAIN ANALYZE is very bad any way you see it.

In other queries (the majority of them), FBSD_TEST is slightly faster than =
LINUX_PROD, e.g
SELECT avg(md.perioddue) from status st,items it,machdefs md WHERE st.id<=
=3D3626961 AND st.apptblidval=3Dit.id AND it.defid=3Dmd.defid;
i get:
=46BSD_DEV : query : 20166,047 ms, EXPLAIN ANALYZE : Total runtime: 74245.5=
76 ms
LINUX_PROD : query : 5908.960 ms, EXPLAIN ANALYZE : Total runtime: 8847.124=
 ms
=46BSD_TEST : query : 4190,873 ms, EXPLAIN ANALYZE : Total runtime: 30334.0=
86 ms

Here we see that although FBSD_TEST is the faster of the 3, its EXPLAIN ANA=
LYZE performance
is nowehere near the plain query.

What could i do to have a better understanding of why this is happening?
Thanx

> 			regards, tom lane
>=20


=2D-=20
Achilleas Mantzios