Re: Postgresql 9.0.2 explain analyze very slow (10x), compared to actual query time

Στις Tuesday 11 January 2011 18:19:11 ο/η Tom Lane έγραψε:
> 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
nevernoticed this in 8.3. 
>
> Same hardware?  What it sounds like is you're running 9.0 on a machine
> with slow gettimeofday().
>

It is on a different hardware. I have three setups here, i have written a small 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=16GB, work_mem=512MB, db size=94GB
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=512MB, work_mem=1MB, db size=76GB
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=5GB, work_mem=512MB, db size=7GB

The FBSD_TEST system,  in the majority of cases seems to outperform LINUX_PROD
(rough impression watching execution times of my app, random benchmarks, nothing too detailed, but it is still a very
fastsystem, 
and i have been testing for over 2 months with this new system, testing 9.0.2 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_DEV.
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=calloc(1,sizeof(struct timeval));
        int runna;
        for (runna=0;runna<1000000;runna++) {
                int rc=gettimeofday(tp,NULL);
                long micros = tp->tv_sec * 1000000 + tp->tv_usec;
                printf("cur_time=%u micro secs\n",micros);
        }
}

For some reason, LINUX_PROD runs this program much much faster than the two FBDs (FBSD_DEV, FBSD_PROD)
I get these values for
% time ./gettimeofday_test > /dev/null
LINUX_PROD real=0m0.373s, user=0m0.364s, sys=0m0.004s
FBSD_DEV real=4.29s, user=0.526s, sys=3.764s
FBSD_TEST real=1.66s, user=0.260s, sys=1.407s

So at least regarding gettimeofday, and setting linux aside, the slower fbsd (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.surname from marinerstates ms,vessels
vsl,marinerm  
where m.id=ms.marinerid and ms.vslid=vsl.id and ms.state='Active' and coalesce(ms.endtime,now())::date >= '2006-07-15'
and 
ms.starttime::date <= '2007-01-11'  and m.marinertype='Mariner'  and m.id not in
(SELECT distinct mold.id from marinerstates msold,vessels vslold,mariner mold  where mold.id=msold.marinerid and
msold.vslid=vslold.idand  
msold.state='Active' and coalesce(msold.endtime,now())::date >= '2006-07-15' and msold.starttime::date <= '2007-01-11'
andexists  
(select 1 from marinerstates msold2 where msold2.marinerid=msold.marinerid and msold2.state='Active' and msold2.id <>
msold.idand  
msold2.starttime<msold.starttime AND (msold.starttime-msold2.endtime)<='18 months')  and mold.marinertype='Mariner' )
order by m.surname,coalesce(m.givenname,''),coalesce(m.midname,'');
with the EXPLAIN ANALYZE version

i get the following execution times: (with \timing) (note however that FBSD_DEV has a considerably smaller database,
theother two are compareable) 
FBSD_DEV : query : 240,419 ms, EXPLAIN ANALYZE query : Total runtime: 538.468 ms
LINUX_PROD : query : 219.568 ms, EXPLAIN ANALYZE query : Total runtime: 216.926 ms
FBSD_TEST : query : 2587,465 ms, EPXLAIN ANALYZE query : Total runtime: 93711.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<=3626961 AND st.apptblidval=it.id AND
it.defid=md.defid;
i get:
FBSD_DEV : query : 20166,047 ms, EXPLAIN ANALYZE : Total runtime: 74245.576 ms
LINUX_PROD : query : 5908.960 ms, EXPLAIN ANALYZE : Total runtime: 8847.124 ms
FBSD_TEST : query : 4190,873 ms, EXPLAIN ANALYZE : Total runtime: 30334.086 ms

Here we see that although FBSD_TEST is the faster of the 3, its EXPLAIN ANALYZE 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
>



--
Achilleas Mantzios