Re: different execution times of the same query

On 20/10/2009 6:51 PM, Luca Ferrari wrote:
> On Tuesday 20 October 2009 10:44:13 am Scott Marlowe's cat walking on the
> keyboard wrote:
>> Two things. 1: Actually running the query and receiving the results
>> isn't the same as just running it and throwing them away (what explain
>> analyze does) and 2: The query may be getting cached in psql if you're
>> running it more than once, but it may not run often enough on that
>> data set to get the same caching each time.
>>
>
>
> You are right, in fact executing:
>
> psql -h localhost -U dataflex cogedb -c "SELECT * FROM GMMOVART WHERE DATA
>> = '01/01/2006' AND DATA <= '31/12/2006' ORDER BY DATA, CONTATORE, RIGA" -o
> /dev/null
>
> produces a log like the following:
>
> cogedb LOG: duration: 8841.152 ms statement: SELECT * FROM GMMOVART WHERE
> DATA >= '01/01/2006' AND DATA <= '31/12/2006' ORDER BY DATA, CONTATORE, RIGA
>
> so 8,8 seconds against 7 seconds, now it sounds compatible. But I was always
> trusting the time of explain analyze, this make me doubt about it. So how is
> such time (explain analyze) to mind?

EXPLAIN ANALYZE measures the time taken to execute the query. It doesn't
include time required to transfer results to the client, possibly write
them to disk, etc. It's really only for examining query plans as
compared to actual execution of that plan.

If you're more interested in *total* query execution time, including
planning, execution, and transfer of results, you should usually use
psql's \timing command, possibly along with output redirection. eg:

x=> explain analyze select * from customer;
QUERY PLAN

--------------------------------------------------------------------------------
------------------------------
Seq Scan on customer (cost=0.00..434.54 rows=12054 width=218) (actual
time=0.0
08..3.941 rows=12054 loops=1)
Total runtime: 6.752 ms
(2 rows)

x=> \timing
Timing is on.
x=> \o out.txt
x=> select * from customer;
Time: 135.571 ms
x=> \timing
Timing is off.
x=> \o
x=>

In both cases the contents of the customer table were cached, as I ran
"SELECT * FROM customer" before starting the test.

As you can see, EXPLAIN ANALYZE is reporting how long it took Pg to
execute the query. The psql \timing command reports how long the whole
process took, including psql reading the data from the postgresql server
and writing it out to the file on disk. Big difference!

--
Craig Ringer