Обсуждение: Suppressing elog.c context messages (was Re: Wait free LW_SHARED acquisition)

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.

The usecases wher eI see this as being useful is high volume debug
logging, not normal messages...

Greetings,

Andres Freund

--Andres Freund                       http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training &
Services

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

On 12/23/14 11:41 AM, Andres Freund wrote:
>>> > >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.

In case anyone picks this up... this problem exists in other places too, such as RAISE DEBUG in plpgsql. I think it'd
beuseful to have clien_min_context and log_min_context that operate akin to *_min_messages but control context output.
 
-- 
Jim Nasby, Data Architect, Blue Treble Consulting
Data in Trouble? Get it in Treble! http://BlueTreble.com

On 2015-01-26 18:30:13 -0600, Jim Nasby wrote:
> On 12/23/14 11:41 AM, Andres Freund wrote:
> >>>> >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.
> 
> In case anyone picks this up... this problem exists in other places too, such as RAISE DEBUG in plpgsql. I think it'd
beuseful to have clien_min_context and log_min_context that operate akin to *_min_messages but control context output.
 

I've pushed it already IIRC. I don't think we can just apply it without
regard for possible users to that many cases - I think the RAISE DEBUG
case is better addressed by a plpgsql option to *optionall* suppress
context, than do it unconditionally. That's discussed somewhere nearby.

-- Andres Freund                       http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training &
Services