Thread

Large time difference between explain analyze and normal run

Chris Kratz <chris.kratz@vistashare.com> — 2005-02-10T18:34:40Z

Does anyone have any idea why there be over a 4s difference between running 
the statement directly and using explain analyze?  Multiple runs give the 
same result and I've tested on several servers.

db=# \timing
Timing is on.
db=# select count(*) from answer;
 count
--------
 530576
(1 row)

Time: 358.805 ms
db=# explain analyze select count(*) from answer;
                                                      QUERY PLAN
----------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=9848.12..9848.12 rows=1 width=0) (actual 
time=4841.231..4841.235 rows=1 loops=1)
   ->  Seq Scan on answer  (cost=0.00..8561.29 rows=514729 width=0) (actual 
time=0.011..2347.762 rows=530576 loops=1)
 Total runtime: 4841.412 ms
(3 rows)

Time: 4855.712 ms

---

Postgresql 7.4.5 running on Linux 2.6.8.1

Re: Large time difference between explain analyze and normal run

Tom Lane <tgl@sss.pgh.pa.us> — 2005-02-10T18:58:37Z

Chris Kratz <chris.kratz@vistashare.com> writes:
> Does anyone have any idea why there be over a 4s difference between running 
> the statement directly and using explain analyze?

>  Aggregate  (cost=9848.12..9848.12 rows=1 width=0) (actual 
> time=4841.231..4841.235 rows=1 loops=1)
>    ->  Seq Scan on answer  (cost=0.00..8561.29 rows=514729 width=0) (actual 
> time=0.011..2347.762 rows=530576 loops=1)
>  Total runtime: 4841.412 ms

EXPLAIN ANALYZE's principal overhead is two gettimeofday() kernel calls
per plan node execution, so 1061154 such calls here.  I infer that
gettimeofday takes about 4 microseconds on your hardware ... which seems
a bit slow for modern machines.  What sort of box is it?

			regards, tom lane

Re: Large time difference between explain analyze and normal run

Chris Kratz <chris.kratz@vistashare.com> — 2005-02-10T19:05:46Z

On Thursday 10 February 2005 01:58 pm, Tom Lane wrote:
> Chris Kratz <chris.kratz@vistashare.com> writes:
> > Does anyone have any idea why there be over a 4s difference between
> > running the statement directly and using explain analyze?
> >
> >  Aggregate  (cost=9848.12..9848.12 rows=1 width=0) (actual
> > time=4841.231..4841.235 rows=1 loops=1)
> >    ->  Seq Scan on answer  (cost=0.00..8561.29 rows=514729 width=0)
> > (actual time=0.011..2347.762 rows=530576 loops=1)
> >  Total runtime: 4841.412 ms
>
> EXPLAIN ANALYZE's principal overhead is two gettimeofday() kernel calls
> per plan node execution, so 1061154 such calls here.  I infer that
> gettimeofday takes about 4 microseconds on your hardware ... which seems
> a bit slow for modern machines.  What sort of box is it?
>
> 			regards, tom lane

OK, that makes sense.

Athlon XP 3000+
1.5G Mem

Is there a way to test the gettimeofday() directly?

Re: Large time difference between explain analyze and normal run

Darcy Buskermolen <darcy@wavefire.com> — 2005-02-10T20:09:42Z

On February 10, 2005 10:58 am, Tom Lane wrote:
> Chris Kratz <chris.kratz@vistashare.com> writes:
> > Does anyone have any idea why there be over a 4s difference between
> > running the statement directly and using explain analyze?
> >
> >  Aggregate  (cost=9848.12..9848.12 rows=1 width=0) (actual
> > time=4841.231..4841.235 rows=1 loops=1)
> >    ->  Seq Scan on answer  (cost=0.00..8561.29 rows=514729 width=0)
> > (actual time=0.011..2347.762 rows=530576 loops=1)
> >  Total runtime: 4841.412 ms
>
> EXPLAIN ANALYZE's principal overhead is two gettimeofday() kernel calls
> per plan node execution, so 1061154 such calls here.  I infer that
> gettimeofday takes about 4 microseconds on your hardware ... which seems
> a bit slow for modern machines.  What sort of box is it?

dvl reported the same thing on #postgresql some months back, and neilc 
was/is/did looking into it.  I belive he came up with a way to move the 
function call outside of the loop  with no ill effects to the rest of the 
expected behavior.

>
> 			regards, tom lane
>
> ---------------------------(end of broadcast)---------------------------
> TIP 4: Don't 'kill -9' the postmaster

-- 
Darcy Buskermolen
Wavefire Technologies Corp.
ph: 250.717.0200
fx:  250.763.1759
http://www.wavefire.com

Re: Large time difference between explain analyze and normal run

Chris Kratz <chris.kratz@vistashare.com> — 2005-02-10T20:25:09Z

On Thursday 10 February 2005 03:09 pm, Darcy Buskermolen wrote:
> On February 10, 2005 10:58 am, Tom Lane wrote:
> > Chris Kratz <chris.kratz@vistashare.com> writes:
> > > Does anyone have any idea why there be over a 4s difference between
> > > running the statement directly and using explain analyze?
> > >
> > >  Aggregate  (cost=9848.12..9848.12 rows=1 width=0) (actual
> > > time=4841.231..4841.235 rows=1 loops=1)
> > >    ->  Seq Scan on answer  (cost=0.00..8561.29 rows=514729 width=0)
> > > (actual time=0.011..2347.762 rows=530576 loops=1)
> > >  Total runtime: 4841.412 ms
> >
> > EXPLAIN ANALYZE's principal overhead is two gettimeofday() kernel calls
> > per plan node execution, so 1061154 such calls here.  I infer that
> > gettimeofday takes about 4 microseconds on your hardware ... which seems
> > a bit slow for modern machines.  What sort of box is it?
>
> dvl reported the same thing on #postgresql some months back, and neilc
> was/is/did looking into it.  I belive he came up with a way to move the
> function call outside of the loop  with no ill effects to the rest of the
> expected behavior.

That's interesting to know.  It's not a big deal, we were just curious as to 
why the difference.  Tom's explanation makes good sense.  We run into the 
same situation with using a profiler on an application, ie measuring incurs 
overhead.  

-Chris