On 2014-12-22 10:35:35 +0530, Amit Kapila wrote:
> On Fri, Dec 19, 2014 at 9:36 PM, Andres Freund <and...@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
>From 5e6af912377a1b43ea0168951238cb6a5e0b233e Mon Sep 17 00:00:00 2001
From: Andres Freund <and...@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
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
