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

Search Discussions

  • Tom Lane at Nov 28, 2003 at 4:48 pm

    Teodor Sigaev 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
  • Marc G. Fournier at Nov 28, 2003 at 5:03 pm

    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
  • Tom Lane at Nov 28, 2003 at 5:14 pm

    "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
  • Marc G. Fournier at Nov 28, 2003 at 6:02 pm

    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
  • Teodor Sigaev at Nov 28, 2003 at 6:06 pm
    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
  • Tom Lane at Nov 28, 2003 at 6:30 pm

    Teodor Sigaev 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
  • Teodor Sigaev at Nov 28, 2003 at 8:08 pm
    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
  • Tom Lane at Nov 28, 2003 at 8:14 pm

    Teodor Sigaev 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

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
grouppgsql-hackers @
categoriespostgresql
postedNov 27, '03 at 2:14p
activeNov 28, '03 at 8:14p
posts9
users3
websitepostgresql.org...
irc#postgresql

People

Translate

site design / logo © 2021 Grokbase