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@sigaev.ru


Thu, 27 Nov 2003 17:13:59 +0300
Teodor Sigaev <teodor@sigaev.ru>
about explain analyze
Teodor Sigaev <teodor@sigaev.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

Fri, 28 Nov 2003 11:48:17 -0500
Tom Lane <tgl@sss.pgh.pa.us>
Re: about explain analyze 
On Fri, 28 Nov 2003, Tom Lane wrote:

> Teodor Sigaev <teodor@sigaev.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@hub.org           Yahoo!: yscrappy              ICQ: 7615664

Fri, 28 Nov 2003 13:00:33 -0400 (AST)
"Marc G. Fournier" <scrappy@postgresql.org>
Re: about explain analyze 
"Marc G. Fournier" <scrappy@postgresql.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

Fri, 28 Nov 2003 12:13:36 -0500
Tom Lane <tgl@sss.pgh.pa.us>
Re: about explain analyze 
On Fri, 28 Nov 2003, Tom Lane wrote:

> "Marc G. Fournier" <scrappy@postgresql.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@hub.org           Yahoo!: yscrappy              ICQ: 7615664

Fri, 28 Nov 2003 13:59:08 -0400 (AST)
"Marc G. Fournier" <scrappy@postgresql.org>
Re: about explain analyze 
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@sigaev.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@sigaev.ru


Fri, 28 Nov 2003 21:05:38 +0300
Teodor Sigaev <teodor@sigaev.ru>
Re: about explain analyze
Teodor Sigaev <teodor@sigaev.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

Fri, 28 Nov 2003 13:29:38 -0500
Tom Lane <tgl@sss.pgh.pa.us>
Re: about explain analyze 
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@sigaev.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@sigaev.ru


Fri, 28 Nov 2003 23:07:43 +0300
Teodor Sigaev <teodor@sigaev.ru>
Re: about explain analyze
Teodor Sigaev <teodor@sigaev.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

Fri, 28 Nov 2003 15:14:09 -0500
Tom Lane <tgl@sss.pgh.pa.us>
Re: about explain analyze 