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 (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers