Re: Suppressing elog.c context messages (was Re: Wait free LW_SHARED acquisition)

On 2014-12-22 10:35:35 +0530, Amit Kapila wrote:
> On Fri, Dec 19, 2014 at 9:36 PM, Andres Freund <andres@2ndquadrant.com>
> wrote:
> >
> > Hi,
> >
> > When debugging lwlock issues I found PRINT_LWDEBUG/LOG_LWDEBUG rather
> > painful to use because of the amount of elog contexts/statements
> > emitted. Given the number of lwlock acquirations that's just not doable.
> >
> > To solve that during development I've solved that by basically
> > replacing:
> >     if (Trace_lwlocks)
> >            elog(LOG, "%s(%s %d): %s", where, name, index, msg);
> >
> > with something like
> >
> >     if (Trace_lwlocks)
> >     {
> >         ErrorContextCallback *old_error_context_stack;
> > ...
> >         old_error_context_stack = error_context_stack;
> >         error_context_stack = NULL;
> >         ereport(LOG,
> >                (errhidestmt(true),
> >                 errmsg("%s(%s %d): %s", where, T_NAME(lock),
> > T_ID(lock), msg)));
> >
> > I think it'd generally be useful to have something like errhidecontext()
> > akin to errhidestatement() to avoid things like the above.
> >
>
> Under this proposal, do you want to suppress the context/statement
> unconditionally or via some hook/variable, because it might be useful to
> print the contexts/statements in certain cases where there is complex
> application and we don't know which part of application code causes
> problem.

I'm proposing to do model it after errhidestatement(). I.e. add
errhidecontext().

I've attached what I was tinkering with when I wrote this message.

> > The usecases wher eI see this as being useful is high volume debug
> > logging, not normal messages...
> >
>
> I think usecase is valid, it is really difficult to dig such a log
> especially when statement size is big.

Right, that was what triggered to look me into it. I'd cases where the
same context was printed thousands of times.

> Also I think even with above, the number
> of logs generated are high for any statement which could still make
> debugging difficult, do you think it would be helpful if PRINT_LWDEBUG
> and LOG_LWDEBUG are used with separate defines (LOCK_DEBUG and
> LOCK_BLOCK_DEBUG) as in certain cases we might want to print info
> about locks which are acquired after waiting or in other words that gets
> blocked.

Hm, that seems like a separate thing. Personally I don't find it
interesting enough to write a patch for it, although I could see it
being interesting for somebody.

If you're looking at that level it's easy enough to just add a early
return in either routine...

Greetings,

Andres Freund