From: Tom Lane <tgl@sss.pgh.pa.us>
To: Achilleas Mantzios <achill@matrix.gatewaynet.com>
Cc: 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 11:45:20 -0500
Message-ID: <27365.1294850720@sss.pgh.pa.us> (raw)
In-Reply-To: <201101121817.11143.achill@matrix.gatewaynet.com>
References: <201101111753.22602.achill@matrix.gatewaynet.com>
<201101121318.44007.achill@matrix.gatewaynet.com>
<25677.1294844873@sss.pgh.pa.us>
<201101121817.11143.achill@matrix.gatewaynet.com>
Achilleas Mantzios <achill@matrix.gatewaynet.com> writes:
> Óôéò Wednesday 12 January 2011 17:07:53 ï/ç Tom Lane Ýãñáøå:
>> 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
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:
> -> 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)
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.
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.
regards, tom lane
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: tgl@sss.pgh.pa.us, achill@matrix.gatewaynet.com
Subject: Re: Postgresql 9.0.2 explain analyze very slow (10x), compared to actual query time
In-Reply-To: <27365.1294850720@sss.pgh.pa.us>
* 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