Re: about explain analyze

Hello!

Explain analyze takes 3 times more time for execution. Why?

wow=# \timing
Timing is on.
wow=# select max(click.accesses) from click;
max
----------
10944762
(1 row)

Time: 105,654 ms
wow=# explain analyze select max(click.accesses) from click;
QUERY PLAN

-----------------------------------------------------------------------------------------------------------------
Aggregate (cost=1103.70..1103.70 rows=1 width=8) (actual
time=289.391..289.393 rows=1 loops=1)
-> Seq Scan on click (cost=0.00..971.36 rows=52936 width=8) (actual
time=0.013..133.943 rows=52936 loops=1)
Total runtime: 289.498 ms
(3 rows)

Time: 290,695 ms
wow=# select version();
version

---------------------------------------------------------------------------------------------------------
PostgreSQL 7.4 on i386-unknown-freebsd5.1, compiled by GCC gcc (GCC) 3.2.2
[FreeBSD] 20030205 (release)
(1 row)

--
Teodor Sigaev E-mail: teodor(at)sigaev(dot)ru

Teodor Sigaev <teodor(at)sigaev(dot)ru> writes:
> Explain analyze takes 3 times more time for execution. Why?

Measurement overhead. It would seem your platform has a particularly
slow version of gettimeofday() though ... I've never noticed such a
large discrepancy myself.

regards, tom lane

On Fri, 28 Nov 2003, Tom Lane wrote:

> Teodor Sigaev <teodor(at)sigaev(dot)ru> writes:
> > Explain analyze takes 3 times more time for execution. Why?
>
> Measurement overhead. It would seem your platform has a particularly
> slow version of gettimeofday() though ... I've never noticed such a
> large discrepancy myself.

Actually, I'm noticing similar "problems" with v7.4 ... "EXPLAIN ANALYZE"
seems to be showing some *very* high ms for execution time, but if you run
the actual query, it doesn't seem to take even 1/10th the time reported
...

This is on a FreeBSD 4.x box ...

----
Marc G. Fournier Hub.Org Networking Services (http://www.hub.org)
Email: scrappy(at)hub(dot)org Yahoo!: yscrappy ICQ: 7615664

"Marc G. Fournier" <scrappy(at)postgresql(dot)org> writes:
> Actually, I'm noticing similar "problems" with v7.4 ... "EXPLAIN ANALYZE"
> seems to be showing some *very* high ms for execution time, but if you run
> the actual query, it doesn't seem to take even 1/10th the time reported
> ...

Example? I don't see anything out of line here.

regards, tom lane

On Fri, 28 Nov 2003, Tom Lane wrote:

> "Marc G. Fournier" <scrappy(at)postgresql(dot)org> writes:
> > Actually, I'm noticing similar "problems" with v7.4 ... "EXPLAIN ANALYZE"
> > seems to be showing some *very* high ms for execution time, but if you run
> > the actual query, it doesn't seem to take even 1/10th the time reported
> > ...
>
> Example? I don't see anything out of line here.

pgsql74# /usr/local/pgsql/bin/psql -U pgsql -c "SELECT count(rec_id) FROM url" 186_archives
count
--------
209872
(1 row)

pgsql74# /usr/local/pgsql/bin/psql -U pgsql -c "EXPLAIN ANALYZE SELECT max(rec_id) FROM url" 186_archives
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------
Aggregate (cost=11177.19..11177.19 rows=1 width=4) (actual time=2400.579..2400.585 rows=1 loops=1)
-> Seq Scan on url (cost=0.00..10741.55 rows=174255 width=4) (actual time=0.056..1387.803 rows=209872 loops=1)
Total runtime: 2407.095 ms
(3 rows)

pgsql74# time /usr/local/pgsql/bin/psql -U pgsql -c "SELECT max(rec_id) FROM url" 186_archives
max
--------
690582
(1 row)

0.000u 0.004s 0:00.32 0.0% 0+0k 0+0io 0pf+0w

----
Marc G. Fournier Hub.Org Networking Services (http://www.hub.org)
Email: scrappy(at)hub(dot)org Yahoo!: yscrappy ICQ: 7615664

How many times is gettimeofday called?
wow=# explain analyze select 1;
QUERY PLAN

------------------------------------------------------------------------------------
Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.008..0.010 rows=1 loops=1)
Total runtime: 0.047 ms
(2 rows)

Several thousands?

Tom Lane wrote:
> Teodor Sigaev <teodor(at)sigaev(dot)ru> writes:
>
>>Explain analyze takes 3 times more time for execution. Why?
>
>
> Measurement overhead. It would seem your platform has a particularly
> slow version of gettimeofday() though ... I've never noticed such a
> large discrepancy myself.
>
> regards, tom lane
>
> ---------------------------(end of broadcast)---------------------------
> TIP 7: don't forget to increase your free space map settings

--
Teodor Sigaev E-mail: teodor(at)sigaev(dot)ru

Teodor Sigaev <teodor(at)sigaev(dot)ru> writes:
> How many times is gettimeofday called?

Twice per plan node visit, if you are doing EXPLAIN ANALYZE. (The
number of "visits" is one more than the number of rows returned.)

regards, tom lane

Tom, I am afraid that I don't understand. My first example:
wow=# explain analyze select max(click.accesses) from click;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------
Aggregate (cost=1103.70..1103.70 rows=1 width=8) (actual
time=289.391..289.393 rows=1 loops=1)
-> Seq Scan on click (cost=0.00..971.36 rows=52936 width=8) (actual
time=0.013..133.943 rows=52936 loops=1)
Total runtime: 289.498 ms
(3 rows)

Time: 290,695 ms

select max() returns only one row... If you mean rows in Seq Scan than
gettimeofday was called (52936+1)*2. Huge value :(

Tom Lane wrote:
> Teodor Sigaev <teodor(at)sigaev(dot)ru> writes:
>
>>How many times is gettimeofday called?
>
>
> Twice per plan node visit, if you are doing EXPLAIN ANALYZE. (The
> number of "visits" is one more than the number of rows returned.)
>
> regards, tom lane
>
> ---------------------------(end of broadcast)---------------------------
> TIP 7: don't forget to increase your free space map settings

--
Teodor Sigaev E-mail: teodor(at)sigaev(dot)ru

Teodor Sigaev <teodor(at)sigaev(dot)ru> writes:
> Tom, I am afraid that I don't understand. My first example:
> wow=# explain analyze select max(click.accesses) from click;
> QUERY PLAN
> -----------------------------------------------------------------------------------------------------------------
> Aggregate (cost=1103.70..1103.70 rows=1 width=8) (actual
> time=289.391..289.393 rows=1 loops=1)
> -> Seq Scan on click (cost=0.00..971.36 rows=52936 width=8) (actual
> time=0.013..133.943 rows=52936 loops=1)
> Total runtime: 289.498 ms
> (3 rows)

> Time: 290,695 ms

> select max() returns only one row... If you mean rows in Seq Scan than
> gettimeofday was called (52936+1)*2. Huge value :(

Right, that many times at the Seq Scan plan node, and (1+1)*2 more times
at the Aggregate node.

regards, tom lane