Обсуждение: Large time difference between explain analyze and normal run
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
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
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?
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
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