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

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Στις Wednesday 12 January 2011 17:07:53 ο/η Tom Lane έγραψε:
> Achilleas Mantzios <achill@xxxxxxxxxxxxxxxxxxxxx> 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
                                                                                                          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)

                                                                                                      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)

-- 
Sent via pgsql-admin mailing list (pgsql-admin@xxxxxxxxxxxxxx)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin

[Index of Archives]     [KVM ARM]     [KVM ia64]     [KVM ppc]     [Virtualization Tools]     [Spice Development]     [Libvirt]     [Libvirt Users]     [Linux USB Devel]     [Linux Audio Users]     [Yosemite Questions]     [Linux Kernel]     [Linux SCSI]     [XFree86]

  Powered by Linux