Обсуждение: Difference between explain analyze and real execution time
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
=?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
> 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
[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?
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
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
=?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
> 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