mirror/postgresql
2
0
Fork 0
mirror of https://git.postgresql.org/git/postgresql.git synced 2024-12-21 08:29:39 +08:00
Code Issues Packages Projects Releases Wiki Activity

Fix performance issue in EXPLAIN (ANALYZE, TIMING OFF).

Browse Source 
Commit af7914c662, which added the TIMING
option to EXPLAIN, had an oversight: if the TIMING option is disabled
then control in InstrStartNode() goes through an elog(DEBUG2) call, which
typically does nothing but takes a noticeable amount of time to do it.
Tweak the logic to avoid that.

In HEAD, also change the elog(DEBUG2)'s in instrument.c to elog(ERROR).
It's not very clear why they weren't like that to begin with, but this
episode shows that not complaining more vociferously about misuse is
likely to do little except allow bugs to remain hidden.

While at it, adjust some code that was making possibly-dangerous
assumptions about flag bits being in the rightmost byte of the
instrument_options word.

Problem reported by Pavel Stehule (via Tomas Vondra).
This commit is contained in:
Tom Lane 2013-02-07 22:53:00 -05:00
parent 9221f9d485
commit bcc6c4c291
1 changed files with 11 additions and 13 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

24
src/backend/executor/instrument.c
View File

@ -33,9 +33,9 @@ InstrAlloc(int n, int instrument_options)
instr = palloc0(n * sizeof(Instrumentation));
if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER))
{
bool need_buffers = (instrument_options & INSTRUMENT_BUFFERS) != 0;
bool need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
int i;
bool need_buffers = instrument_options & INSTRUMENT_BUFFERS;
bool need_timer = instrument_options & INSTRUMENT_TIMER;
for (i = 0; i < n; i++)
{
@ -51,10 +51,13 @@ InstrAlloc(int n, int instrument_options)
void
InstrStartNode(Instrumentation *instr)
{
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");
if (instr->need_timer)
{
if (INSTR_TIME_IS_ZERO(instr->starttime))
INSTR_TIME_SET_CURRENT(instr->starttime);
else
elog(ERROR, "InstrStartNode called twice in a row");
}
/* save buffer usage totals at node entry, if needed */
if (instr->need_bufusage)
@ -73,18 +76,13 @@ InstrStopNode(Instrumentation *instr, double nTuples)
/* let's update the time only if the timer was requested */
if (instr->need_timer)
{
if (INSTR_TIME_IS_ZERO(instr->starttime))
{
elog(DEBUG2, "InstrStopNode called without start");
return;
}
elog(ERROR, "InstrStopNode called without start");
INSTR_TIME_SET_CURRENT(endtime);
INSTR_TIME_ACCUM_DIFF(instr->counter, endtime, instr->starttime);
INSTR_TIME_SET_ZERO(instr->starttime);
}
/* Add delta of buffer usage since entry to node's totals */
@ -111,7 +109,7 @@ InstrEndLoop(Instrumentation *instr)
return;
if (!INSTR_TIME_IS_ZERO(instr->starttime))
elog(DEBUG2, "InstrEndLoop called on running node");
elog(ERROR, "InstrEndLoop called on running node");
/* Accumulate per-cycle statistics into totals */
totaltime = INSTR_TIME_GET_DOUBLE(instr->counter);