pg.ddx.io pgsql-admin@postgresql.org mailing list archive help / color / mirror / Atom feed From: Achilleas Mantzios <achill@matrix.gatewaynet.com>
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 18:17:10 +0200
Message-ID: <201101121817.11143.achill@matrix.gatewaynet.com> (raw )
In-Reply-To: <25677.1294844873@sss.pgh.pa.us >
References: <201101111753.22602.achill@matrix.gatewaynet.com >
<201101121318.44007.achill@matrix.gatewaynet.com >
<25677.1294844873@sss.pgh.pa.us >
Óôéò Wednesday 12 January 2011 17:07:53 ï/ç Tom Lane Ýãñáøå:
> Achilleas Mantzios <achill@matrix.gatewaynet.com> writes:
> > 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);
> > }
> > }
>
> Right offhand I'd wonder whether that was more bound by gettimeofday or
> by printf. Please try it without printf in the loop.
>
Changed that to smth like: micros_total = micros_total + (double) micros;
instead of the printf to beat any compiler optimization, and still linux runs at light speed:
FBSD_TEST : user 0.089s, sys 1.4s
FBSD_DEV : user 0.183s, sys 3.8s
LINUX_PROD : user 0.168s, sys 0s
(regarding that gettimeofday is a syscall in FreeBSD, and that sys time is 0 for linux, makes me think some optimization is being done)
> > 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 shared_buffers setting seems way out of line compared to actual
> memory on this machine. Maybe it's swapping.
>
I tried with what pgtune suggests (1920MB) and i get same results.
For the simple query: 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;
still FBSD_TEST runs faster than LINUX_PROD smth like (3.5 secs VS 5.8 secs)
> > i get the following execution times: (with \timing) (note however that FBSD_DEV has a considerably smaller database, the other 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.
>
> Are they in fact the same query plans in each case?
The query plans seem to differ. A lot of seq scans in the FBSD case.
I attach the query plans for LINUX_PROD, FBSD_TEST (the times did not change noticeably after the new shared_buffers setting)
>
> regards, tom lane
>
--
Achilleas Mantzios
Attachments:
2tom_linuxprod_query_plan.txt (text/plain, 4.5K) download
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Unique (cost=860732.31..860761.51 rows=2336 width=22) (actual time=221.113..221.472 rows=577 loops=1)
-> Sort (cost=860732.31..860738.15 rows=2336 width=22) (actual time=221.110..221.220 rows=577 loops=1)
Sort Key: m.surname, (COALESCE(m.givenname, ''::character varying)), (COALESCE(m.midname, ''::character varying)), m.id
Sort Method: quicksort Memory: 69kB
-> Hash Join (cost=856660.40..860601.61 rows=2336 width=22) (actual time=169.164..220.490 rows=577 loops=1)
Hash Cond: (ms.vslid = vsl.id)
-> Hash Join (cost=856620.20..860526.95 rows=2958 width=26) (actual time=168.871..219.793 rows=577 loops=1)
Hash Cond: (ms.marinerid = m.id)
-> Seq Scan on marinerstates ms (cost=0.00..3793.75 rows=6067 width=8) (actual time=0.012..48.267 rows=2630 loops=1)
Filter: (((state)::text = 'Active'::text) AND ((starttime)::date <= '2007-01-11'::date) AND ((COALESCE(endtime, now()))::date >= '2006-07-15'::date))
-> Hash (cost=856509.66..856509.66 rows=8843 width=22) (actual time=168.810..168.810 rows=14518 loops=1)
-> Index Scan using mariner_pkey on mariner m (cost=854253.06..856509.66 rows=8843 width=22) (actual time=144.906..162.369 rows=14518 loops=1)
Filter: ((NOT (hashed subplan)) AND ((marinertype)::text = 'Mariner'::text))
SubPlan
-> Unique (cost=0.00..854247.22 rows=2336 width=4) (actual time=0.079..143.656 rows=1448 loops=1)
-> Merge Join (cost=0.00..854241.38 rows=2336 width=4) (actual time=0.078..142.634 rows=1824 loops=1)
Merge Cond: (msold.marinerid = mold.id)
-> Nested Loop (cost=0.00..851962.29 rows=2396 width=4) (actual time=0.065..122.789 rows=1888 loops=1)
-> Index Scan using marinerstates_marinerid on marinerstates msold (cost=0.00..850980.53 rows=3034 width=8) (actual time=0.059..116.367 rows=1888 loops=1)
Filter: (((state)::text = 'Active'::text) AND ((starttime)::date <= '2007-01-11'::date) AND ((COALESCE(endtime, now()))::date >= '2006-07-15'::date) AND (subplan))
SubPlan
-> Bitmap Heap Scan on marinerstates msold2 (cost=4.28..12.14 rows=1 width=0) (actual time=0.007..0.007 rows=1 loops=2630)
Recheck Cond: ((marinerid = $0) AND (starttime < $2))
Filter: ((id <> $1) AND ((state)::text = 'Active'::text) AND (($2 - endtime) <= '1 year 6 mons'::interval))
-> Bitmap Index Scan on marinerstates_marinerid_starttime (cost=0.00..4.28 rows=2 width=0) (actual time=0.004..0.004 rows=6 loops=2630)
Index Cond: ((marinerid = $0) AND (starttime < $2))
-> Index Scan using vessels_pkey on vessels vslold (cost=0.00..0.31 rows=1 width=4) (actual time=0.002..0.002 rows=1 loops=1888)
Index Cond: (vslold.id = msold.vslid)
-> Index Scan using mariner_pkey on mariner mold (cost=0.00..2211.26 rows=17687 width=4) (actual time=0.007..15.142 rows=14619 loops=1)
Filter: ((mold.marinertype)::text = 'Mariner'::text)
-> Hash (cost=35.09..35.09 rows=409 width=4) (actual time=0.284..0.284 rows=288 loops=1)
-> Seq Scan on vessels vsl (cost=0.00..35.09 rows=409 width=4) (actual time=0.012..0.173 rows=288 loops=1)
Total runtime: 221.846 ms
(33 rows)
2tom_fbsdtest_query_plan.txt (text/plain, 4.9K) download
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Unique (cost=13987.87..14042.86 rows=4399 width=23) (actual time=93406.457..93409.135 rows=577 loops=1)
-> Sort (cost=13987.87..13998.87 rows=4399 width=23) (actual time=93406.452..93407.334 rows=577 loops=1)
Sort Key: m.surname, (COALESCE(m.givenname, ''::character varying)), (COALESCE(m.midname, ''::character varying)), m.id
Sort Method: quicksort Memory: 69kB
-> Hash Join (cost=9977.51..13721.67 rows=4399 width=23) (actual time=93347.321..93404.790 rows=577 loops=1)
Hash Cond: (ms.marinerid = m.id)
-> Hash Join (cost=26.46..3671.64 rows=4399 width=4) (actual time=1.040..52.180 rows=2630 loops=1)
Hash Cond: (ms.vslid = vsl.id)
-> Seq Scan on marinerstates ms (cost=0.00..3579.82 rows=5698 width=8) (actual time=0.012..42.739 rows=2630 loops=1)
Filter: (((state)::text = 'Active'::text) AND ((starttime)::date <= '2007-01-11'::date) AND ((COALESCE(endtime, now()))::date >= '2006-07-15'::date))
-> Hash (cost=22.87..22.87 rows=287 width=4) (actual time=1.014..1.014 rows=287 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 11kB
-> Seq Scan on vessels vsl (cost=0.00..22.87 rows=287 width=4) (actual time=0.003..0.539 rows=287 loops=1)
-> Hash (cost=9851.59..9851.59 rows=7957 width=23) (actual time=93346.204..93346.204 rows=14466 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 790kB
-> Seq Scan on mariner m (cost=9185.74..9851.59 rows=7957 width=23) (actual time=93288.927..93321.136 rows=14466 loops=1)
Filter: ((NOT (hashed SubPlan 1)) AND ((marinertype)::text = 'Mariner'::text))
SubPlan 1
-> Unique (cost=3390.49..9185.74 rows=1 width=4) (actual time=279.920..93285.790 rows=1448 loops=1)
-> Nested Loop (cost=3390.49..9185.73 rows=1 width=4) (actual time=279.916..93280.499 rows=1824 loops=1)
Join Filter: (msold.marinerid = mold.id)
-> Index Scan using mariner_pkey on mariner mold (cost=0.00..1957.89 rows=15914 width=4) (actual time=0.009..38.449 rows=15914 loops=1)
Filter: ((marinertype)::text = 'Mariner'::text)
-> Materialize (cost=3390.49..6989.13 rows=1 width=8) (actual time=0.013..2.881 rows=1888 loops=15914)
-> Nested Loop (cost=3390.49..6989.13 rows=1 width=8) (actual time=189.468..267.483 rows=1888 loops=1)
-> Hash Semi Join (cost=3390.49..6988.83 rows=1 width=12) (actual time=189.452..248.136 rows=1888 loops=1)
Hash Cond: (msold.marinerid = msold2.marinerid)
Join Filter: ((msold2.id <> msold.id) AND (msold2.starttime < msold.starttime) AND ((msold.starttime - msold2.endtime) <= '1 year 6 mons'::interval))
-> Seq Scan on marinerstates msold (cost=0.00..3579.82 rows=5698 width=20) (actual time=0.004..42.507 rows=2630 loops=1)
Filter: (((state)::text = 'Active'::text) AND ((starttime)::date <= '2007-01-11'::date) AND ((COALESCE(endtime, now()))::date >= '2006-07-15'::date))
-> Hash (cost=2749.41..2749.41 rows=51286 width=24) (actual time=189.351..189.351 rows=51391 loops=1)
Buckets: 8192 Batches: 1 Memory Usage: 2798kB
-> Seq Scan on marinerstates msold2 (cost=0.00..2749.41 rows=51286 width=24) (actual time=0.003..102.133 rows=51391 loops=1)
Filter: ((state)::text = 'Active'::text)
-> Index Scan using vessels_pkey on vessels vslold (cost=0.00..0.28 rows=1 width=4) (actual time=0.002..0.004 rows=1 loops=1888)
Index Cond: (vslold.id = msold.vslid)
Total runtime: 93410.498 ms
(37 rows)
view thread (25+ messages) latest in thread
Message-ID: <201101121817.11143.achill@matrix.gatewaynet.com>
Permalink: ../201101121817.11143.achill@matrix.gatewaynet.com/
Also on: postgresql.org/message-id/201101121817.11143.achill@matrix.gatewaynet.com
copy link · copy postgr.es
reply Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-admin@postgresql.org
Cc: achill@matrix.gatewaynet.com
Subject: Re: Postgresql 9.0.2 explain analyze very slow (10x), compared to actual query time
In-Reply-To: <201101121817.11143.achill@matrix.gatewaynet.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox