Received: from maia.hub.org (maia-2.hub.org [200.46.204.251]) by mail.postgresql.org (Postfix) with ESMTP id EDB5C1337B5E for ; Thu, 13 Jan 2011 08:13:31 -0400 (AST) Received: from mail.postgresql.org ([200.46.204.86]) by maia.hub.org (mx1.hub.org [200.46.204.251]) (amavisd-maia, port 10024) with ESMTP id 59973-08 for ; Thu, 13 Jan 2011 12:13:24 +0000 (UTC) X-Greylist: from auto-whitelisted by SQLgrey-1.7.6 Received: from smadev.internal.net (host3.dynacom.ondsl.gr [62.103.35.211]) by mail.postgresql.org (Postfix) with ESMTP id CB13B1337B79 for ; Thu, 13 Jan 2011 08:13:22 -0400 (AST) Received: from smadev.internal.net (localhost.internal.net [127.0.0.1]) by smadev.internal.net (8.14.2/8.14.2) with ESMTP id p0DCDM7s090747 for ; Thu, 13 Jan 2011 14:13:22 +0200 (EET) (envelope-from achill@matrix.gatewaynet.com) Received: from localhost (localhost [[UNIX: localhost]]) by smadev.internal.net (8.14.2/8.14.2/Submit) id p0DCDMEP090746 for pgsql-admin@postgresql.org; Thu, 13 Jan 2011 14:13:22 +0200 (EET) (envelope-from achill@matrix.gatewaynet.com) From: Achilleas Mantzios 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: Thu, 13 Jan 2011 14:13:21 +0200 User-Agent: KMail/1.9.7 References: <201101111753.22602.achill@matrix.gatewaynet.com> <201101121817.11143.achill@matrix.gatewaynet.com> <27365.1294850720@sss.pgh.pa.us> In-Reply-To: <27365.1294850720@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: <201101131413.21757.achill@matrix.gatewaynet.com> X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=-0.451 tagged_above=-10 required=5 tests=BAYES_00=-1.9, RCVD_IN_BRBL_LASTEXT=1.449 X-Spam-Level: X-Archive-Number: 201101/67 X-Sequence-Number: 36507 =D3=F4=E9=F2 Wednesday 12 January 2011 18:45:20 =EF/=E7 Tom Lane =DD=E3=F1= =E1=F8=E5: > Achilleas Mantzios writes: > > =D3=F4=E9=F2 Wednesday 12 January 2011 17:07:53 =EF/=E7 Tom Lane =DD=E3= =F1=E1=F8=E5: > >> Right offhand I'd wonder whether that was more bound by gettimeofday or > >> by printf. Please try it without printf in the loop. >=20 > > Changed that to smth like: micros_total =3D micros_total + (double) mic= ros; > > instead of the printf to beat any compiler optimization, and still linu= x 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 >=20 > Well, there's your problem all right: the FBSD_DEV system takes 22X > longer to execute gettimeofday() than the LINUX_PROD system. The > particular plan that 9.0 is choosing is especially vulnerable to this > because it involves a whole lot of calls of the Materialize plan node: >=20 > > -> Nested Loop (cost=3D3390.49..91= 85.73 rows=3D1 width=3D4) (actual time=3D279.916..93280.499 rows=3D1824 loo= ps=3D1) > > Join Filter: (msold.marinerid = =3D mold.id) > > -> Index Scan using mariner_p= key on mariner mold (cost=3D0.00..1957.89 rows=3D15914 width=3D4) (actual = time=3D0.009..38.449 rows=3D15914 loops=3D1) > > Filter: ((marinertype)::= text =3D 'Mariner'::text) > > -> Materialize (cost=3D3390.= 49..6989.13 rows=3D1 width=3D8) (actual time=3D0.013..2.881 rows=3D1888 loo= ps=3D15914) >=20 > You've got 1888 * 15914 * 2 gettimeofday() calls needed to count up the > time spent in Materialize, which at 3.8usec apiece adds up to ... hmm > ... I get 228 seconds, which is more than the reported runtime. So I > think there's something wrong with your measurement of the gettimeofday > cost. But I wouldn't be a bit surprised to hear that the true cost of > gettimeofday on that machine is a microsecond or so, in which case all > of the EXPLAIN ANALYZE time bloat is indeed due to that. >=20 > This problem has been discussed repeatedly on the pgsql-performance > list, which is where your question really belongs, not here. The short > of it is that cheap motherboards tend to provide cheap clock hardware > that takes about a microsecond to read. It also helps to be running > an OS that is able to read the clock in userspace without invoking a > kernel call. It looks like your Linux box is winning on both counts > compared to your BSD boxes. Just comparing the two FBSD boxes on equal terms gives crazy results, so I'll try to leave LINUX out of the equation for a while, and also i'll try = to leave the=20 difference in DB sizes out of the equation so what i did was make a dump of= the small DB=20 on the small (slow) FBSD box (FBSD_DEV) and load it on the bigger (fast) FB= SD box (FBSD_TEST). I set : sysctl kern.timecounter.hardware=3DTSC on both systems and now the below program #include #include #include int main(int argc,char** argv) { struct timeval *tp=3Dcalloc(1,sizeof(struct timeval)); int runna; long double micros_total=3D0; for (runna=3D0;runna<1000000;runna++) { int rc=3Dgettimeofday(tp,NULL); long micros =3D tp->tv_sec * 1000000 + tp->tv_usec; micros_total =3D micros_total + (long double) micros; } printf("micros_total=3D%LE\n",micros_total); } % time ./gettimeofday_test gives=20 =46BSD_DEV (slow) : 0.127u 0.231s 0:00.35 100.0% 5+192k 0+0io 0pf+0w =46BSD_TEST (fast) : 0.002u 0.014s 0:00.15 6.6% 84+24192k 0+0io 0pf+0w Database on the fast system, as i said is exactly the same as in the slow o= ne. The query "SELECT avg(md.perioddue) from status st,items it,machdefs md WHE= RE st.apptblidval=3Dit.id AND it.defid=3Dmd.defid;" gives with \timing =46BSD_DEV (slow) : Time: 28747,374 ms, EXPLAIN ANALYZE: Total runtime: 318= 16.648 ms=20 =46BSD_TEST (fast) : Time: 3153,372 ms, EXPLAIN ANALYZE: Total runtime: 570= 1.942 ms (the fast system is indeed a lot faster on this one (by 10x)) However the query (known from the initial mail as well) 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= mold where mold.id=3Dmsold.marinerid and msold.vslid=3Dvslold.id=20 and msold.state=3D'Active' and coalesce(msold.endtime,now())::date >= =3D '2006-07-15' and msold.starttime::date <=3D '2007-01-11' and exists=20 (select 1 from marinerstates msold2 where msold2.marinerid=3Dmsold= =2Emarinerid and msold2.state=3D'Active' and msold2.id <> msold.id and=20 msold2.starttime Sort (cost=3D633677.56..633682.14 rows=3D1834 width=3D23) (actual t= ime=3D270.182..270.440 rows=3D603 loops=3D1) Sort Key: m.surname, (COALESCE(m.givenname, ''::character varying)= ), (COALESCE(m.midname, ''::character varying)), m.id Sort Method: quicksort Memory: 53kB -> Hash Join (cost=3D630601.65..633578.15 rows=3D1834 width=3D23= ) (actual time=3D194.815..269.294 rows=3D603 loops=3D1) Hash Cond: (ms.vslid =3D vsl.id) -> Hash Join (cost=3D630580.33..633530.01 rows=3D2261 widt= h=3D27) (actual time=3D194.444..268.140 rows=3D603 loops=3D1) Hash Cond: (ms.marinerid =3D m.id) -> Seq Scan on marinerstates ms (cost=3D0.00..2875.3= 2 rows=3D4599 width=3D8) (actual time=3D0.012..70.281 rows=3D2625 loops=3D1) Filter: (((state)::text =3D 'Active'::text) AND = ((starttime)::date <=3D '2007-01-11'::date) AND ((COALESCE(endtime, now()))= ::date >=3D ' 2006-07-15'::date)) -> Hash (cost=3D630491.54..630491.54 rows=3D7103 wid= th=3D23) (actual time=3D194.391..194.391 rows=3D12832 loops=3D1) -> Index Scan using mariner_pkey on mariner m = (cost=3D628776.89..630491.54 rows=3D7103 width=3D23) (actual time=3D162.607= =2E.184.282 rows=3D 12832 loops=3D1) Filter: ((NOT (hashed subplan)) AND ((mari= nertype)::text =3D 'Mariner'::text)) SubPlan -> Unique (cost=3D0.00..628772.30 rows= =3D1834 width=3D4) (actual time=3D0.064..161.099 rows=3D1454 loops=3D1) -> Nested Loop (cost=3D0.00..628= 767.72 rows=3D1834 width=3D4) (actual time=3D0.062..159.091 rows=3D1835 loo= ps=3D1) -> Nested Loop (cost=3D0.0= 0..627027.98 rows=3D1865 width=3D4) (actual time=3D0.056..147.464 rows=3D18= 76 loops=3D1) -> Index Scan using m= arinerstates_marinerid on marinerstates msold (cost=3D0.00..626316.07 rows= =3D2299 wid th=3D8) (actual time=3D0.050..138.100 rows=3D1876 loops=3D1) Filter: (((state= )::text =3D 'Active'::text) AND ((starttime)::date <=3D '2007-01-11'::date)= AND ((COAL ESCE(endtime, now()))::date >=3D '2006-07-15'::date) AND (subplan)) SubPlan -> Bitmap Hea= p Scan on marinerstates msold2 (cost=3D4.28..12.11 rows=3D1 width=3D0) (ac= tual time=3D0.0 08..0.008 rows=3D1 loops=3D2625) Recheck = Cond: ((marinerid =3D $0) AND (starttime < $2)) Filter: = ((id <> $1) AND ((state)::text =3D 'Active'::text) AND (($2 - endtime) <=3D= '1 year 6 mons'::interval)) -> Bitm= ap Index Scan on marinerstates_marinerid_starttime (cost=3D0.00..4.28 rows= =3D2 width=3D 0) (actual time=3D0.005..0.005 rows=3D6 loops=3D2625) In= dex Cond: ((marinerid =3D $0) AND (starttime < $2)) -> Index Scan using v= essels_pkey on vessels vslold (cost=3D0.00..0.30 rows=3D1 width=3D4) (actu= al time=3D0.002 =2E.0.003 rows=3D1 loops=3D1876) Index Cond: (vsl= old.id =3D msold.vslid) -> Index Scan using mariner= _pkey on mariner mold (cost=3D0.00..0.92 rows=3D1 width=3D4) (actual time= =3D0.004..0.004 rows=3D1 loops=3D1876) Index Cond: (mold.id = =3D msold.marinerid) Filter: ((mold.mariner= type)::text =3D 'Mariner'::text) -> Hash (cost=3D17.81..17.81 rows=3D281 width=3D4) (actual= time=3D0.363..0.363 rows=3D272 loops=3D1) -> Seq Scan on vessels vsl (cost=3D0.00..17.81 rows= =3D281 width=3D4) (actual time=3D0.009..0.199 rows=3D272 loops=3D1) Total runtime: 271.466 ms =46BSD_TEST: Unique (cost=3D11525.09..11571.55 rows=3D3717 width=3D23) (actual time=3D1= 0455.286..10455.635 rows=3D603 loops=3D1) -> Sort (cost=3D11525.09..11534.38 rows=3D3717 width=3D23) (actual tim= e=3D10455.285..10455.390 rows=3D603 loops=3D1) Sort Key: m.surname, (COALESCE(m.givenname, ''::character varying)= ), (COALESCE(m.midname, ''::character varying)), m.id Sort Method: quicksort Memory: 71kB -> Hash Join (cost=3D8281.98..11304.67 rows=3D3717 width=3D23) (= actual time=3D10418.032..10454.399 rows=3D603 loops=3D1) Hash Cond: (ms.marinerid =3D m.id) -> Hash Join (cost=3D20.12..2963.83 rows=3D3717 width=3D4)= (actual time=3D0.199..34.986 rows=3D2625 loops=3D1) Hash Cond: (ms.vslid =3D vsl.id) -> Seq Scan on marinerstates ms (cost=3D0.00..2889.3= 2 rows=3D4590 width=3D8) (actual time=3D0.015..33.507 rows=3D2625 loops=3D1) Filter: (((state)::text =3D 'Active'::text) AND = ((starttime)::date <=3D '2007-01-11'::date) AND ((COALESCE(endtime, now()))= ::date >=3D ' 2006-07-15'::date)) -> Hash (cost=3D16.72..16.72 rows=3D272 width=3D4) (= actual time=3D0.179..0.179 rows=3D272 loops=3D1) Buckets: 1024 Batches: 1 Memory Usage: 10kB -> Seq Scan on vessels vsl (cost=3D0.00..16.72= rows=3D272 width=3D4) (actual time=3D0.003..0.099 rows=3D272 loops=3D1) -> Hash (cost=3D8172.57..8172.57 rows=3D7143 width=3D23) (= actual time=3D10417.803..10417.803 rows=3D12832 loops=3D1) Buckets: 1024 Batches: 1 Memory Usage: 702kB -> Seq Scan on mariner m (cost=3D7614.86..8172.57 ro= ws=3D7143 width=3D23) (actual time=3D10402.282..10412.840 rows=3D12832 loop= s=3D1) Filter: ((NOT (hashed SubPlan 1)) AND ((marinert= ype)::text =3D 'Mariner'::text)) SubPlan 1 -> Unique (cost=3D2768.00..7614.86 rows=3D1 = width=3D4) (actual time=3D85.291..10401.289 rows=3D1454 loops=3D1) -> Nested Loop (cost=3D2768.00..7614.8= 6 rows=3D1 width=3D4) (actual time=3D85.290..10400.399 rows=3D1835 loops=3D= 1) Join Filter: (msold.marinerid =3D = mold.id) -> Index Scan using mariner_pkey = on mariner mold (cost=3D0.00..1728.60 rows=3D14286 width=3D4) (actual time= =3D0.007..13.53 1 rows=3D14286 loops=3D1) Filter: ((marinertype)::text= =3D 'Mariner'::text) -> Materialize (cost=3D2768.00..= 5671.97 rows=3D1 width=3D8) (actual time=3D0.003..0.329 rows=3D1876 loops= =3D14286) -> Nested Loop (cost=3D276= 8.00..5671.96 rows=3D1 width=3D8) (actual time=3D37.502..83.326 rows=3D1876= loops=3D1) -> Hash Semi Join (c= ost=3D2768.00..5671.67 rows=3D1 width=3D12) (actual time=3D37.491..79.434 r= ows=3D1876 loops=3D 1) Hash Cond: (msol= d.marinerid =3D msold2.marinerid) Join Filter: ((m= sold2.id <> msold.id) AND (msold2.starttime < msold.starttime) AND ((msold.= startti me - msold2.endtime) <=3D '1 year 6 mons'::interval)) -> Seq Scan on = marinerstates msold (cost=3D0.00..2889.32 rows=3D4590 width=3D20) (actual = time=3D0.004..3 4.281 rows=3D2625 loops=3D1) Filter: ((= (state)::text =3D 'Active'::text) AND ((starttime)::date <=3D '2007-01-11':= :date) AND ((COALESCE(endtime, now()))::date >=3D '2006-07-15'::date)) -> Hash (cost= =3D2251.66..2251.66 rows=3D41307 width=3D24) (actual time=3D37.446..37.446 = rows=3D41250 loops=3D1) Buckets: 8= 192 Batches: 1 Memory Usage: 2246kB =2D> Seq Scan on marinerstates msold2 (cost=3D0.00..2251.66 rows=3D41307 = width=3D24) (actual time=3D0.002..23.350 rows=3D41250 loops=3D1) Filt= er: ((state)::text =3D 'Active'::text) -> Index Scan using v= essels_pkey on vessels vslold (cost=3D0.00..0.28 rows=3D1 width=3D4) (actu= al time=3D0.001..0.001 rows=3D1 loops=3D1876) Index Cond: (vsl= old.id =3D msold.vslid) Total runtime: 10456.092 ms So the questions remain, a) Why do we have "EXPLAIN ANALYZE" in FBSD_TEST (fast) taking an order of = magnitude slower than the actual query. b) Why this particular query is so slow on this generally much faster syste= m. PS I agree that this is a lot "performance" related, but the "EXPLAIN ANALYZE"= part just dont seem right. Thats why i posted on admin in the first place. >=20 > regards, tom lane >=20 =2D-=20 Achilleas Mantzios