Re: performance bug in instrument.c

Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Tomas Vondra <tv(at)fuzzy(dot)cz> writes:
> 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)
>>     {
>>         if (INSTR_TIME_IS_ZERO(instr->starttime))
>>       INSTR_TIME_SET_CURRENT(instr->starttime);
>>         else
>>             elog(DEBUG2, "InstrStartNode called twice in a row");
>>     }
>
> Hm.  It's a bit annoying that we can't detect the "called twice"
> condition when !need_timer, but I suppose that any such bug would be a
> caller logic error that would probably not be sensitive to need_timer,
> so it's likely not worth adding overhead to handle that.

Yes, that's annoying. But if we need / want to detect that, wouldn't it
be cleaner to add there a separate "already executed" flag, instead of
misusing starttime for that?

>
> A bigger question is why this is elog(DEBUG2) and not elog(ERROR).
> Had it been the latter, we'd have noticed the mistake immediately.
> The current choice might be masking any caller-logic errors that
> exist, too.

Not sure why it's DEBUG2, but if it really is an error then it should be
logged as ERROR I guess.

Tomas