Hi,
it seems there's a issue in instrument.c that may have significant
performance impact for some plans when running explain analyze with
"TIMING OFF".
There's this piece of code in InstrStartNode:
if (instr->need_timer && INSTR_TIME_IS_ZERO(instr->starttime))
INSTR_TIME_SET_CURRENT(instr->starttime);
else
elog(DEBUG2, "InstrStartNode called twice in a row");
but it should actually be like this
if (instr->need_timer && INSTR_TIME_IS_ZERO(instr->starttime))
INSTR_TIME_SET_CURRENT(instr->starttime);
else if (instr->need_timer)
elog(DEBUG2, "InstrStartNode called twice in a row");
or maybe
if (instr->need_timer)
{
if (INSTR_TIME_IS_ZERO(instr->starttime))
INSTR_TIME_SET_CURRENT(instr->starttime);
else
elog(DEBUG2, "InstrStartNode called twice in a row");
}
The current code calls the "else" branch everytime when "TIMING OFF" is
used, and this may lead to serious performance degradation - see for
example this:
CREATE TABLE x AS SELECT id FROM generate_series(1,15000) s(id);
ANALYZE x;
EXPLAIN ANALYZE SELECT a.id FROM x a, x b;
Current code:
QUERY PLAN
-----------------------------------------------------------------------
Nested Loop (cost=0.00..2812971.50 rows=225000000 width=4) (actual
time=0.013..29611.859 rows=225000000 loops=1)
-> Seq Scan on x a (cost=0.00..217.00 rows=15000 width=4) (actual
time=0.006..2.847 rows=15000 loops=1)
-> Materialize (cost=0.00..292.00 rows=15000 width=0) (actual
time=0.000..0.740 rows=15000 loops=15000)
-> Seq Scan on x b (cost=0.00..217.00 rows=15000 width=0)
(actual time=0.003..1.186 rows=15000 loops=1)
Total runtime: 36054.079 ms
(5 rows)
and with the fix
QUERY PLAN
-----------------------------------------------------------------------
Nested Loop (cost=0.00..1458333.00 rows=116640000 width=4) (actual
time=0.021..13158.399 rows=100000000 loops=1)
-> Seq Scan on x a (cost=0.00..153.00 rows=10800 width=4) (actual
time=0.014..1.960 rows=10000 loops=1)
-> Materialize (cost=0.00..207.00 rows=10800 width=0) (actual
time=0.000..0.499 rows=10000 loops=10000)
-> Seq Scan on x b (cost=0.00..153.00 rows=10800 width=0)
(actual time=0.003..1.037 rows=10000 loops=1)
Total runtime: 16017.953 ms
(5 rows)
Obviously this is a quite extreme example, most plans won't be hit this
hard.
This was discovered by Pavel Stehule when backporting my "TIMING OFF"
patch (which introduced the bug).
regards
Tomas
--
Sent via pgsql-hackers mailing list ([email protected])
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
