pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedDifference between explain analyze and real execution time
8+ messages / 4 participants
[nested] [flat]
* Difference between explain analyze and real execution time
@ 2010-11-15 08:21 Artur Zając <azajac@ang.com.pl>
2010-11-15 15:12 ` Re: Difference between explain analyze and real execution time Tom Lane <tgl@sss.pgh.pa.us>
2010-11-15 19:39 ` Re: Difference between explain analyze and real execution time Robert Haas <robertmhaas@gmail.com>
0 siblings, 2 replies; 8+ messages in thread
From: Artur Zając @ 2010-11-15 08:21 UTC (permalink / raw)
To: pgsql-performance
I have some simple query (executed with time command):
time psql -c 'explain analyze SELECT te.idt FROM t_positions AS te JOIN
t_st AS stm ON (te.idt=stm.idt AND 4=stm.idm) WHERE te.idtr IN (347186)'
QUERY
PLAN
----------------------------------------------------------------------------
----------------------------------------------------------------------------
Nested Loop (cost=0.00..33.33 rows=2 width=4) (actual time=0.297..0.418
rows=3 loops=1)
-> Index Scan using t_positions_index1 on t_positions te
(cost=0.00..8.43 rows=3 width=4) (actual time=0.140..0.148 rows=3 loops=1)
Index Cond: (idtr = 347186)
-> Index Scan using t_st_index4 on t_st stm (cost=0.00..8.29 rows=1
width=4) (actual time=0.078..0.079 rows=1 loops=3)
Index Cond: ((stm.idt = te.idt) AND (4 = stm.idm))
Total runtime: 0.710 ms
(6 rows)
real 0m3.309s
user 0m0.002s
sys 0m0.002s
Why there is so big difference between explain analyze (0.710 ms) and real
execution time (3309 ms)? Any suggestions?
Psql only execution time:
time psql -c 'explain analyze SELECT blabla()'
ERROR: function blabla() does not exist
real 0m0.011s
user 0m0.001s
sys 0m0.004s
SELECT version();
PostgreSQL 9.0.1 on i686-pc-linux-gnu, compiled by GCC gcc (GCC) 4.1.2
20070502 (Red Hat 4.1.2-12), 32-bit
-------------------------------------------
Artur Zajac
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Difference between explain analyze and real execution time
2010-11-15 08:21 Difference between explain analyze and real execution time Artur Zając <azajac@ang.com.pl>
@ 2010-11-15 15:12 ` Tom Lane <tgl@sss.pgh.pa.us>
2010-11-15 15:24 ` Re: Difference between explain analyze and real execution time Artur Zając <azajac@ang.com.pl>
2010-11-15 15:25 ` Re: Difference between explain analyze and real execution time Tobias Brox <tobixen@gmail.com>
1 sibling, 2 replies; 8+ messages in thread
From: Tom Lane @ 2010-11-15 15:12 UTC (permalink / raw)
To: Artur Zając <azajac@ang.com.pl>; +Cc: pgsql-performance
=?iso-8859-2?Q?Artur_Zaj=B1c?= <azajac@ang.com.pl> writes:
> Why there is so big difference between explain analyze (0.710 ms) and real
> execution time (3309 ms)?
EXPLAIN ANALYZE doesn't account for all of the runtime involved. In
this case, I'd bet that session startup/shutdown is a big part of the
difference.
regards, tom lane
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Difference between explain analyze and real execution time
2010-11-15 08:21 Difference between explain analyze and real execution time Artur Zając <azajac@ang.com.pl>
2010-11-15 15:12 ` Re: Difference between explain analyze and real execution time Tom Lane <tgl@sss.pgh.pa.us>
@ 2010-11-15 15:24 ` Artur Zając <azajac@ang.com.pl>
1 sibling, 0 replies; 8+ messages in thread
From: Artur Zając @ 2010-11-15 15:24 UTC (permalink / raw)
To: pgsql-performance
> EXPLAIN ANALYZE doesn't account for all of the runtime involved. In this
case, I'd bet that session startup/shutdown is a big part of the difference.
>
> regards, tom lane
Does session startup/shutdown depend on tables used in query? Some simpler
query:
time psql -c 'explain analyze SELECT te.idt FROM t_positions AS te WHERE
te.idtr IN (347186)'
QUERY PLAN
----------------------------------------------------------------------------
---------------------------------------------------------
Index Scan using tg_transelem_index1 on tg_transelem te (cost=0.00..8.43
rows=3 width=4) (actual time=0.130..0.134 rows=3 loops=1)
Index Cond: (tr_idtrans = 347186)
Total runtime: 0.211 ms
real 0m0.017s
user 0m0.002s
sys 0m0.004s
-------------------------------------------
Artur Zajac
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Difference between explain analyze and real execution time
2010-11-15 08:21 Difference between explain analyze and real execution time Artur Zając <azajac@ang.com.pl>
2010-11-15 15:12 ` Re: Difference between explain analyze and real execution time Tom Lane <tgl@sss.pgh.pa.us>
@ 2010-11-15 15:25 ` Tobias Brox <tobixen@gmail.com>
1 sibling, 0 replies; 8+ messages in thread
From: Tobias Brox @ 2010-11-15 15:25 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: Artur Zając <azajac@ang.com.pl>; pgsql-performance
[Tom Lane]
> EXPLAIN ANALYZE doesn't account for all of the runtime involved. In
> this case, I'd bet that session startup/shutdown is a big part of the
> difference.
The session startup/shutdown should be the same for the real SQL and
the broken SQL, shouldn't it?
[Artur Zając]
> time psql -c 'explain analyze SELECT te.idt FROM t_positions AS te
> JOIN t_st AS stm ON (te.idt=stm.idt AND 4=stm.idm) WHERE te.idtr IN
> (347186)'
Is this weidness only observed for this query? What happens with
other queries? "explain analyze select 1"? "explain analyze select *
from t_positions where idtr=347816"? plain select without "explain
analyze"? etc?
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Difference between explain analyze and real execution time
2010-11-15 08:21 Difference between explain analyze and real execution time Artur Zając <azajac@ang.com.pl>
@ 2010-11-15 19:39 ` Robert Haas <robertmhaas@gmail.com>
2010-11-15 20:43 ` Re: Difference between explain analyze and real execution time Artur Zając <azajac@ang.com.pl>
1 sibling, 1 reply; 8+ messages in thread
From: Robert Haas @ 2010-11-15 19:39 UTC (permalink / raw)
To: Artur Zając <azajac@ang.com.pl>; +Cc: pgsql-performance
2010/11/15 Artur Zając <azajac@ang.com.pl>:
> Why there is so big difference between explain analyze (0.710 ms) and real
> execution time (3309 ms)? Any suggestions?
Could it be that it takes a long time to plan for some reason? How
fast is a plain EXPLAIN?
What happens if you start up psql, turn on \timing, and then run
EXPLAIN ANALYZE from within an interactive session? That's usually a
better way to test, as it avoids counting the session-startup
overhead.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Difference between explain analyze and real execution time
2010-11-15 08:21 Difference between explain analyze and real execution time Artur Zając <azajac@ang.com.pl>
2010-11-15 19:39 ` Re: Difference between explain analyze and real execution time Robert Haas <robertmhaas@gmail.com>
@ 2010-11-15 20:43 ` Artur Zając <azajac@ang.com.pl>
2010-11-15 21:03 ` Re: Difference between explain analyze and real execution time Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 1 reply; 8+ messages in thread
From: Artur Zając @ 2010-11-15 20:43 UTC (permalink / raw)
To: 'Robert Haas' <robertmhaas@gmail.com>; +Cc: pgsql-performance
2010/11/15 Artur Zając <azajac@ang.com.pl>:
> Why there is so big difference between explain analyze (0.710 ms) and
> real execution time (3309 ms)? Any suggestions?
> Could it be that it takes a long time to plan for some reason? How fast
is a plain EXPLAIN?
Yes! That is it :) Planning is painful. I'm so stupid. I didn't check VACUUM
without ANALYZE :)
time psql -c 'explain SELECT te.idt FROM t_positions AS te WHERE te.idtr
IN (347186)'
real 0m1.087s
user 0m0.004s
sys 0m0.001s
I've changed default_statistics_target to 10000 and I think that is a
reason. When I changed it to 1000 everything seems to be ok:
time psql -c 'explain analyze SELECT te.idt FROM t_positions AS te WHERE
te.idtr IN (347186)'
real 0m0.062s
user 0m0.003s
sys 0m0.004s
Thanks.
-------------------------------------------
Artur Zajac
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Difference between explain analyze and real execution time
2010-11-15 08:21 Difference between explain analyze and real execution time Artur Zając <azajac@ang.com.pl>
2010-11-15 19:39 ` Re: Difference between explain analyze and real execution time Robert Haas <robertmhaas@gmail.com>
2010-11-15 20:43 ` Re: Difference between explain analyze and real execution time Artur Zając <azajac@ang.com.pl>
@ 2010-11-15 21:03 ` Tom Lane <tgl@sss.pgh.pa.us>
2010-11-15 21:30 ` Re: Difference between explain analyze and real execution time Artur Zając <azajac@ang.com.pl>
0 siblings, 1 reply; 8+ messages in thread
From: Tom Lane @ 2010-11-15 21:03 UTC (permalink / raw)
To: Artur Zając <azajac@ang.com.pl>; +Cc: 'Robert Haas' <robertmhaas@gmail.com>; pgsql-performance
=?iso-8859-2?Q?Artur_Zaj=B1c?= <azajac@ang.com.pl> writes:
> I've changed default_statistics_target to 10000 and I think that is a
> reason.
That's certainly going to cost you something, but this seems like a
mighty large slowdown, especially for a non-join query. What datatype
is te.idtr, anyway?
regards, tom lane
^ permalink raw reply [nested|flat] 8+ messages in thread
* Re: Difference between explain analyze and real execution time
2010-11-15 08:21 Difference between explain analyze and real execution time Artur Zając <azajac@ang.com.pl>
2010-11-15 19:39 ` Re: Difference between explain analyze and real execution time Robert Haas <robertmhaas@gmail.com>
2010-11-15 20:43 ` Re: Difference between explain analyze and real execution time Artur Zając <azajac@ang.com.pl>
2010-11-15 21:03 ` Re: Difference between explain analyze and real execution time Tom Lane <tgl@sss.pgh.pa.us>
@ 2010-11-15 21:30 ` Artur Zając <azajac@ang.com.pl>
0 siblings, 0 replies; 8+ messages in thread
From: Artur Zając @ 2010-11-15 21:30 UTC (permalink / raw)
To: 'Tom Lane' <tgl@sss.pgh.pa.us>; +Cc: 'Robert Haas' <robertmhaas@gmail.com>; pgsql-performance
> I've changed default_statistics_target to 10000 and I think that is a
> reason.
> That's certainly going to cost you something, but this seems like a mighty
large slowdown, especially for a non-join query. What datatype is te.idtr,
anyway?
Integer not null and primary key of t_positions table.
Table t_positions has about 1500000 records, table t_st about 130000
records.
-------------------------------------------
Artur Zajac
^ permalink raw reply [nested|flat] 8+ messages in thread
end of thread, other threads:[~2010-11-15 21:30 UTC | newest]
Thread overview: 8+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2010-11-15 08:21 Difference between explain analyze and real execution time Artur Zając <azajac@ang.com.pl>
2010-11-15 15:12 ` Tom Lane <tgl@sss.pgh.pa.us>
2010-11-15 15:24 ` Artur Zając <azajac@ang.com.pl>
2010-11-15 15:25 ` Tobias Brox <tobixen@gmail.com>
2010-11-15 19:39 ` Robert Haas <robertmhaas@gmail.com>
2010-11-15 20:43 ` Artur Zając <azajac@ang.com.pl>
2010-11-15 21:03 ` Tom Lane <tgl@sss.pgh.pa.us>
2010-11-15 21:30 ` Artur Zając <azajac@ang.com.pl>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox