Re: Finding query execution time using \timing and EXPLAIN ANALYZE..

Satalabaha Postgres <satalabaha(dot)postgres(at)gmail(dot)com> writes:
> I was trying to get elapsed time for the sql using the \timing command in
> psql as well as EXPLAIN ANALYZE.. I see both the commands reporting
> different elapsed time. And this is after repeated execution of the same
> query and not the first execution. In this case, which one would be the
> right execution time for the query.

They're presumably both accurate, but they aren't measuring the same
thing. psql's \timing reports the end-to-end time from the client's
perspective. EXPLAIN ANALYZE reports the time for two components
of the server's processing. So \timing includes all of these:

1. Transmission of the query across the network to the server
2. Parsing and parse analysis of the query
3. Rewriting (a/k/a view expansion) of the query
4. Planning
5. Execution
6. Formatting of the query results as text
7. Transmission of the results across the network to the client.

while EXPLAIN is only telling you about steps 4 and 5.

Having said that, I'm a bit baffled by the size of the difference.
This example doesn't look like any of the other steps should take
very long: it's a short simple query, there doesn't seem to be
any view involved, and the result is only one row. Unless maybe
you're using tin-cans-and-string for the network connection?

There are various effects whereby the first execution of a query
can take longer than repeat executions, but you said you'd
controlled for that.

Also, how stable are these numbers if you repeat them several
times? It might be mostly about noise and/or the effects of
CPU power management. On my Linux box I find that I don't
get very reproducible numbers for short queries unless I've
done "sudo cpupower frequency-set --governor performance".

regards, tom lane