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
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
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.
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
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
Attachments:
0001-Add-capability-to-suppress-CONTEXT-messages-to-elog-.patchtext/x-patch; charset=us-asciiDownload
>From 5e6af912377a1b43ea0168951238cb6a5e0b233e Mon Sep 17 00:00:00 2001
From: Andres Freund <andres@anarazel.de>
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 errfunction(const char *funcname);
extern int errposition(int cursorpos);
@@ -385,6 +386,7 @@ typedef struct ErrorData
bool output_to_client; /* will report to client? */
bool show_funcname; /* true to force funcname inclusion */
bool hide_stmt; /* true to prevent STATEMENT: inclusion */
+ bool hide_ctx; /* true to prevent CONTEXT: inclusion */
const char *filename; /* __FILE__ of ereport() call */
int lineno; /* __LINE__ of ereport() call */
const char *funcname; /* __func__ of ereport() call */
--
2.2.0.rc0.18.ga1ad247
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
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