Re: Suppressing elog.c context messages (was Re: [HACKERS] Wait free LW_SHARED acquisition)
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 be useful 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 -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: Suppressing elog.c context messages (was Re: [HACKERS] Wait free LW_SHARED acquisition)
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 be useful 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 -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: Suppressing elog.c context messages (was Re: [HACKERS] 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
> 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
>From 5e6af912377a1b43ea0168951238cb6a5e0b233e Mon Sep 17 00:00:00 2001
From: Andres Freund
Date: Sun, 21 Dec 2014 15:45:55 +0100
Subject: [PATCH 1/4] Add capability to suppress CONTEXT: messages to elog
machinery.
Hiding context messages usually is not a good idea - except for rather
verbose debugging/development utensils like LOG_DEBUG. There the
amount of repeated context messages just bloat the log without adding
information.
---
src/backend/utils/error/elog.c | 24 ++--
src/include/utils/elog.h | 2 ++
2 files changed, 24 insertions(+), 2 deletions(-)
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 2316464..8f04b19 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -1081,6 +1081,25 @@ errhidestmt(bool hide_stmt)
return 0; /* return value does not matter */
}
+/*
+ * errhidestmt --- optionally suppress CONTEXT: field of log entry
+ *
+ * This should only be used for verbose debugging messages where the repeated
+ * inclusion of CONTEXT: bloats the log volume too much.
+ */
+int
+errhidecontext(bool hide_ctx)
+{
+ ErrorData *edata = &errordata[errordata_stack_depth];
+
+ /* we don't bother incrementing recursion_depth */
+ CHECK_STACK_DEPTH();
+
+ edata->hide_ctx = hide_ctx;
+
+ return 0; /* return value does not matter */
+}
+
/*
* errfunction --- add reporting function name to the current error
@@ -2724,7 +2743,8 @@ write_csvlog(ErrorData *edata)
appendStringInfoChar(&buf, ',');
/* errcontext */
- appendCSVLiteral(&buf, edata->context);
+ if (!edata->hide_ctx)
+ appendCSVLiteral(&buf, edata->context);
appendStringInfoChar(&buf, ',');
/* user query --- only reported if not disabled by the caller */
@@ -2856,7 +2876,7 @@ send_message_to_server_log(ErrorData *edata)
append_with_tabs(&buf, edata->internalquery);
appendStringInfoChar(&buf, '\n');
}
- if (edata->context)
+ if (edata->context && !edata->hide_ctx)
{
log_line_prefix(&buf, edata);
appendStringInfoString(&buf, _("CONTEXT: "));
diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
index 87438b8..ec7ed22 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -221,6 +221,7 @@ errcontext_msg(const char *fmt,...)
__attribute__((format(PG_PRINTF_ATTRIBUTE, 1, 2)));
extern int errhidestmt(bool hide_stmt);
+extern int errhidecontext(bool hide_ctx);
extern int errf
Re: Suppressing elog.c context messages (was Re: [HACKERS] Wait free LW_SHARED acquisition)
On Fri, Dec 19, 2014 at 9:36 PM, Andres Freund
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.
> 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. 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.
With Regards,
Amit Kapila.
EnterpriseDB: http://www.enterprisedb.com
Suppressing elog.c context messages (was Re: [HACKERS] 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
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
