performance bug in instrument.c
От | Tomas Vondra |
---|---|
Тема | performance bug in instrument.c |
Дата | |
Msg-id | 51142323.2070803@fuzzy.cz обсуждение исходный текст |
Ответы |
Re: performance bug in instrument.c
(Tom Lane <tgl@sss.pgh.pa.us>)
Re: performance bug in instrument.c (Tomas Vondra <tv@fuzzy.cz>) |
Список | pgsql-hackers |
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); elseif (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=225000000width=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=116640000width=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
В списке pgsql-hackers по дате отправления: