query logging of prepared statements
A couple months ago, I implemented prepared statements for PyGreSQL. While
updating our application in advance of their release with that feature, I
noticed that our query logs were several times larger.
With non-prepared statements, we logged to CSV:
|message | SELECT 1
With SQL EXECUTE, we log:
|message | statement: EXECUTE sqlex(2);
|detail | prepare: prepare sqlex AS SELECT $1;
With PQexecPrepared, we would log:
|message | execute qq: PREPARE qq AS SELECT $1
|detail | parameters: $1 = '3'
For comparison, with PQexecParams, the logs I see look like this (apparently
the "unnamed" prepared statement is used behind the scenes):
|message | execute <unnamed>: SELECT [...]
It's not clear to me why it'd be desirable for the previous PREPARE to be
additionally logged during every execution, instead of just its name (in
"message") and params (in "detail"). (Actually, I had to triple check that it
wasn't somehow executing a prepared statement which itself created a prepared
statement...)
For us, the performance benefit is to minimize the overhead (mostly in pygres)
of many INSERTs into append-only tables. It's not great that a feature
intended to improve performance is causing 2x more log volume to be written.
Also, it seems odd that for SQL EXECUTE, the PREPARE is shown in "detail", but
for the library call, it's shown in "message".
I found:
|commit bc24d5b97673c365f19be21f83acca3c184cf1a7
|Author: Bruce Momjian <bruce@momjian.us>
|Date: Tue Aug 29 02:11:30 2006 +0000
|
| Now bind displays prepare as detail, and execute displays prepare and
| optionally bind. I re-added the "statement:" label so people will
| understand why the line is being printed (it is log_*statement
| behavior).
|
| Use single quotes for bind values, instead of double quotes, and double
| literal single quotes in bind values (and document that). I also made
| use of the DETAIL line to have much cleaner output.
and:
|commit c8961bf1ce0b51019db31c5572dac18b664e02f1
|Author: Bruce Momjian <bruce@momjian.us>
|Date: Fri Aug 4 18:53:46 2006 +0000
|
| Improve logging of protocol-level prepared statements.
Justin
On Fri, Feb 08, 2019 at 07:29:53AM -0600, Justin Pryzby wrote:
A couple months ago, I implemented prepared statements for PyGreSQL. While
updating our application in advance of their release with that feature, I
noticed that our query logs were several times larger.
Previously sent to -general (and quoted fully below), resending to -hackers
with patch.
/messages/by-id/20190208132953.GF29720@telsasoft.com
I propose that the prepared statement associated with an EXECUTE should only be
included in log "DETAIL" when log_error_verbosity=VERBOSE, for both SQL EXECUTE
and PQexecPrepared. I'd like to be able to continue logging DETAIL (including
bind parameters), so want like to avoid setting "TERSE" just to avoid redundant
messages.
With attached patch, I'm not sure if !*portal_name && !portal->prepStmtName
would catch cases other than PQexecParams (?)
Compare unpatched server to patched server to patched server with
log_error_verbosity=verbose.
|$ psql postgres -xtc "SET log_error_verbosity=default;SET log_statement='all'; SET client_min_messages=log" -c "PREPARE q AS SELECT 2" -c "EXECUTE q"
|SET
|LOG: statement: PREPARE q AS SELECT 2
|PREPARE
|LOG: statement: EXECUTE q
|DETAIL: prepare: PREPARE q AS SELECT 2
|?column? | 2
|$ PGHOST=/tmp PGPORT=5678 psql postgres -xtc "SET log_error_verbosity=default;SET log_statement='all'; SET client_min_messages=log" -c "PREPARE q AS SELECT 2" -c "EXECUTE q"
|SET
|LOG: statement: PREPARE q AS SELECT 2
|PREPARE
|LOG: statement: EXECUTE q
|?column? | 2
|$ PGHOST=/tmp PGPORT=5678 psql postgres -xtc "SET log_error_verbosity=verbose;SET log_statement='all'; SET client_min_messages=log" -c "PREPARE q AS SELECT 2" -c "EXECUTE q"
|SET
|LOG: statement: PREPARE q AS SELECT 2
|PREPARE
|LOG: statement: EXECUTE q
|DETAIL: prepare: PREPARE q AS SELECT 2
|?column? | 2
For PQexecPrepared library call:
|$ xPGPORT=5678 xPGHOST=/tmp PYTHONPATH=../PyGreSQL/build/lib.linux-x86_64-2.7/ python2.7 -c "import pg; d=pg.DB('postgres'); d.query('SET client_min_messages=log; SET log_error_verbosity=default; SET log_statement=\"all\"'); d.query('SELECT 1; PREPARE q AS SELECT \$1'); d.query_prepared('q',[1]); d.query_formatted('SELECT %s', [2])"
|LOG: statement: SELECT 1; PREPARE q AS SELECT $1
|LOG: execute q: SELECT 1; PREPARE q AS SELECT $1
|DETAIL: parameters: $1 = '1'
|LOG: execute <unnamed>: SELECT $1
|DETAIL: parameters: $1 = '2'
|$ PGPORT=5678 PGHOST=/tmp PYTHONPATH=../PyGreSQL/build/lib.linux-x86_64-2.7/ python2.7 -c "import pg; d=pg.DB('postgres'); d.query('SET client_min_messages=log; SET log_error_verbosity=default; SET log_statement=\"all\"'); d.query('SELECT 1; PREPARE q AS SELECT \$1'); d.query_prepared('q',[1]); d.query_formatted('SELECT %s', [2])"
|LOG: statement: SELECT 1; PREPARE q AS SELECT $1
|LOG: execute q
|DETAIL: parameters: $1 = '1'
|LOG: execute <unnamed>: SELECT $1
|DETAIL: parameters: $1 = '2'
|$ PGPORT=5678 PGHOST=/tmp PYTHONPATH=../PyGreSQL/build/lib.linux-x86_64-2.7/ python2.7 -c "import pg; d=pg.DB('postgres'); d.query('SET client_min_messages=log; SET log_error_verbosity=verbose; SET log_statement=\"all\"'); d.query('SELECT 1; PREPARE q AS SELECT \$1'); d.query_prepared('q',[1]); d.query_formatted('SELECT %s', [2])"
|LOG: statement: SELECT 1; PREPARE q AS SELECT $1
|LOG: execute q: SELECT 1; PREPARE q AS SELECT $1
|DETAIL: parameters: $1 = '1'
|LOG: execute <unnamed>: SELECT $1
|DETAIL: parameters: $1 = '2'
Also, I noticed that if the statement was prepared using SQL PREPARE (rather
than PQprepare), and if it used simple query with multiple commands, they're
all included in the log, like this when executed with PQexecPrepared:
|LOG: execute q: SET log_error_verbosity=verbose; SET client_min_messages=log; PREPARE q AS SELECT $1
And looks like this for SQL EXECUTE:
|[pryzbyj@telsasoft-db postgresql]$ psql postgres -txc "SET client_min_messages=log;SELECT 1;PREPARE q AS SELECT 2" -c "EXECUTE q"
|PREPARE
|LOG: statement: EXECUTE q
|DETAIL: prepare: SET client_min_messages=log;SELECT 1;PREPARE q AS SELECT 2
|?column? | 2
Show quoted text
On Fri, Feb 08, 2019 at 07:29:53AM -0600, Justin Pryzby wrote:
A couple months ago, I implemented prepared statements for PyGreSQL. While
updating our application in advance of their release with that feature, I
noticed that our query logs were several times larger.With non-prepared statements, we logged to CSV:
|message | SELECT 1With SQL EXECUTE, we log:
|message | statement: EXECUTE sqlex(2);
|detail | prepare: prepare sqlex AS SELECT $1;With PQexecPrepared, we would log:
|message | execute qq: PREPARE qq AS SELECT $1
|detail | parameters: $1 = '3'For comparison, with PQexecParams, the logs I see look like this (apparently
the "unnamed" prepared statement is used behind the scenes):
|message | execute <unnamed>: SELECT [...]It's not clear to me why it'd be desirable for the previous PREPARE to be
additionally logged during every execution, instead of just its name (in
"message") and params (in "detail"). (Actually, I had to triple check that it
wasn't somehow executing a prepared statement which itself created a prepared
statement...)For us, the performance benefit is to minimize the overhead (mostly in pygres)
of many INSERTs into append-only tables. It's not great that a feature
intended to improve performance is causing 2x more log volume to be written.Also, it seems odd that for SQL EXECUTE, the PREPARE is shown in "detail", but
for the library call, it's shown in "message".I found:
|commit bc24d5b97673c365f19be21f83acca3c184cf1a7
|Author: Bruce Momjian <bruce@momjian.us>
|Date: Tue Aug 29 02:11:30 2006 +0000
|
| Now bind displays prepare as detail, and execute displays prepare and
| optionally bind. I re-added the "statement:" label so people will
| understand why the line is being printed (it is log_*statement
| behavior).
|
| Use single quotes for bind values, instead of double quotes, and double
| literal single quotes in bind values (and document that). I also made
| use of the DETAIL line to have much cleaner output.and:
|commit c8961bf1ce0b51019db31c5572dac18b664e02f1
|Author: Bruce Momjian <bruce@momjian.us>
|Date: Fri Aug 4 18:53:46 2006 +0000
|
| Improve logging of protocol-level prepared statements.Justin
Attachments:
0001-Conditionally-re-log-prepared-statement-during-execu.patchtext/x-diff; charset=us-asciiDownload
From 21c504144f378e9c24198476c14a32a3021cd95c Mon Sep 17 00:00:00 2001
From: Justin Pryzby <justin@telsasoft.com>
Date: Sat, 9 Feb 2019 19:20:43 -0500
Subject: [PATCH] Conditionally re-log prepared statement during execution
Now controlled by log_error_verbosity>=PGERROR_VERBOSE.
---
src/backend/tcop/postgres.c | 23 ++++++++++++++++++-----
1 file changed, 18 insertions(+), 5 deletions(-)
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 36cfd507b2..622e780d3d 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1042,7 +1042,7 @@ exec_simple_query(const char *query_string)
ereport(LOG,
(errmsg("statement: %s", query_string),
errhidestmt(true),
- errdetail_execute(parsetree_list)));
+ Log_error_verbosity>=PGERROR_VERBOSE ? errdetail_execute(parsetree_list) : 0));
was_logged = true;
}
@@ -1966,6 +1966,7 @@ exec_execute_message(const char *portal_name, long max_rows)
bool is_xact_command;
bool execute_is_fetch;
bool was_logged = false;
+ bool log_prepared;
char msec_str[32];
/* Adjust destination to tell printtup.c what to do */
@@ -2058,18 +2059,29 @@ exec_execute_message(const char *portal_name, long max_rows)
*/
execute_is_fetch = !portal->atStart;
+ /*
+ * Log "execute <unnamed>: ..." rather than just "execute <unnamed>"
+ * when using the unnamed portal and unamed perpared statements, which
+ * are used behind the scenes by PQexecParams.
+ * XXX: if anything else uses unnamed portal+unnamed prepared, then the
+ * prepared statement will be logged on every EXECUTE.
+ */
+ log_prepared = (!*portal_name && !portal->prepStmtName) ||
+ Log_error_verbosity>=PGERROR_VERBOSE;
+
/* Log immediately if dictated by log_statement */
if (check_log_statement(portal->stmts))
{
ereport(LOG,
- (errmsg("%s %s%s%s: %s",
+ (errmsg("%s %s%s%s%s%s",
execute_is_fetch ?
_("execute fetch from") :
_("execute"),
prepStmtName,
*portal_name ? "/" : "",
*portal_name ? portal_name : "",
- sourceText),
+ log_prepared ? ": " : "",
+ log_prepared ? sourceText : ""),
errhidestmt(true),
errdetail_params(portalParams)));
was_logged = true;
@@ -2150,7 +2162,7 @@ exec_execute_message(const char *portal_name, long max_rows)
break;
case 2:
ereport(LOG,
- (errmsg("duration: %s ms %s %s%s%s: %s",
+ (errmsg("duration: %s ms %s %s%s%s%s%s",
msec_str,
execute_is_fetch ?
_("execute fetch from") :
@@ -2158,7 +2170,8 @@ exec_execute_message(const char *portal_name, long max_rows)
prepStmtName,
*portal_name ? "/" : "",
*portal_name ? portal_name : "",
- sourceText),
+ log_prepared ? ": " : "",
+ log_prepared ? sourceText : ""),
errhidestmt(true),
errdetail_params(portalParams)));
break;
--
2.12.2
Sigh, resending to -hackers for real.
On Fri, Feb 08, 2019 at 07:29:53AM -0600, Justin Pryzby wrote:
A couple months ago, I implemented prepared statements for PyGreSQL. While
updating our application in advance of their release with that feature, I
noticed that our query logs were several times larger.
Previously sent to -general (and quoted fully below), resending to -hackers
with patch.
/messages/by-id/20190208132953.GF29720@telsasoft.com
https://www.postgresql.org/docs/current/runtime-config-logging.html
I propose that the prepared statement associated with an EXECUTE should be
included in log "DETAIL" only when log_error_verbosity=VERBOSE, for both SQL
EXECUTE and PQexecPrepared (if at all). I'd like to be able to continue
logging DETAIL (including bind parameters), so want like to avoid setting
"TERSE" just to avoid redundant messages. (It occurs to me that the GUC should
probably stick to its existing documented behavior rather than be extended,
which suggests that the duplicitive portions of the logs should simply be
removed, rather than conditionalized. Let me know what you think).
With attached patch, I'm not sure if !*portal_name && !portal->prepStmtName
would catch cases other than PQexecParams (?)
Compare unpatched server to patched server to patched server with
log_error_verbosity=verbose.
|$ psql postgres -xtc "SET log_error_verbosity=default;SET log_statement='all'; SET client_min_messages=log" -c "PREPARE q AS SELECT 2" -c "EXECUTE q"
|SET
|LOG: statement: PREPARE q AS SELECT 2
|PREPARE
|LOG: statement: EXECUTE q
|DETAIL: prepare: PREPARE q AS SELECT 2
|?column? | 2
|$ PGHOST=/tmp PGPORT=5678 psql postgres -xtc "SET log_error_verbosity=default;SET log_statement='all'; SET client_min_messages=log" -c "PREPARE q AS SELECT 2" -c "EXECUTE q"
|SET
|LOG: statement: PREPARE q AS SELECT 2
|PREPARE
|LOG: statement: EXECUTE q
|?column? | 2
|$ PGHOST=/tmp PGPORT=5678 psql postgres -xtc "SET log_error_verbosity=verbose;SET log_statement='all'; SET client_min_messages=log" -c "PREPARE q AS SELECT 2" -c "EXECUTE q"
|SET
|LOG: statement: PREPARE q AS SELECT 2
|PREPARE
|LOG: statement: EXECUTE q
|DETAIL: prepare: PREPARE q AS SELECT 2
|?column? | 2
For PQexecPrepared library call:
|$ xPGPORT=5678 xPGHOST=/tmp PYTHONPATH=../PyGreSQL/build/lib.linux-x86_64-2.7/ python2.7 -c "import pg; d=pg.DB('postgres'); d.query('SET client_min_messages=log; SET log_error_verbosity=default; SET log_statement=\"all\"'); d.query('SELECT 1; PREPARE q AS SELECT \$1'); d.query_prepared('q',[1]); d.query_formatted('SELECT %s', [2])"
|LOG: statement: SELECT 1; PREPARE q AS SELECT $1
|LOG: execute q: SELECT 1; PREPARE q AS SELECT $1
|DETAIL: parameters: $1 = '1'
|LOG: execute <unnamed>: SELECT $1
|DETAIL: parameters: $1 = '2'
|$ PGPORT=5678 PGHOST=/tmp PYTHONPATH=../PyGreSQL/build/lib.linux-x86_64-2.7/ python2.7 -c "import pg; d=pg.DB('postgres'); d.query('SET client_min_messages=log; SET log_error_verbosity=default; SET log_statement=\"all\"'); d.query('SELECT 1; PREPARE q AS SELECT \$1'); d.query_prepared('q',[1]); d.query_formatted('SELECT %s', [2])"
|LOG: statement: SELECT 1; PREPARE q AS SELECT $1
|LOG: execute q
|DETAIL: parameters: $1 = '1'
|LOG: execute <unnamed>: SELECT $1
|DETAIL: parameters: $1 = '2'
|$ PGPORT=5678 PGHOST=/tmp PYTHONPATH=../PyGreSQL/build/lib.linux-x86_64-2.7/ python2.7 -c "import pg; d=pg.DB('postgres'); d.query('SET client_min_messages=log; SET log_error_verbosity=verbose; SET log_statement=\"all\"'); d.query('SELECT 1; PREPARE q AS SELECT \$1'); d.query_prepared('q',[1]); d.query_formatted('SELECT %s', [2])"
|LOG: statement: SELECT 1; PREPARE q AS SELECT $1
|LOG: execute q: SELECT 1; PREPARE q AS SELECT $1
|DETAIL: parameters: $1 = '1'
|LOG: execute <unnamed>: SELECT $1
|DETAIL: parameters: $1 = '2'
Also, I noticed that if the statement was prepared using SQL PREPARE (rather
than PQprepare), and if it used simple query with multiple commands, they're
all included in the log, like this when executed with PQexecPrepared:
|LOG: execute q: SET log_error_verbosity=verbose; SET client_min_messages=log; PREPARE q AS SELECT $1
And looks like this for SQL EXECUTE:
|[pryzbyj@telsasoft-db postgresql]$ psql postgres -txc "SET client_min_messages=log;SELECT 1;PREPARE q AS SELECT 2" -c "EXECUTE q"
|PREPARE
|LOG: statement: EXECUTE q
|DETAIL: prepare: SET client_min_messages=log;SELECT 1;PREPARE q AS SELECT 2
|?column? | 2
Show quoted text
On Fri, Feb 08, 2019 at 07:29:53AM -0600, Justin Pryzby wrote:
A couple months ago, I implemented prepared statements for PyGreSQL. While
updating our application in advance of their release with that feature, I
noticed that our query logs were several times larger.With non-prepared statements, we logged to CSV:
|message | SELECT 1With SQL EXECUTE, we log:
|message | statement: EXECUTE sqlex(2);
|detail | prepare: prepare sqlex AS SELECT $1;With PQexecPrepared, we would log:
|message | execute qq: PREPARE qq AS SELECT $1
|detail | parameters: $1 = '3'For comparison, with PQexecParams, the logs I see look like this (apparently
the "unnamed" prepared statement is used behind the scenes):
|message | execute <unnamed>: SELECT [...]It's not clear to me why it'd be desirable for the previous PREPARE to be
additionally logged during every execution, instead of just its name (in
"message") and params (in "detail"). (Actually, I had to triple check that it
wasn't somehow executing a prepared statement which itself created a prepared
statement...)For us, the performance benefit is to minimize the overhead (mostly in pygres)
of many INSERTs into append-only tables. It's not great that a feature
intended to improve performance is causing 2x more log volume to be written.Also, it seems odd that for SQL EXECUTE, the PREPARE is shown in "detail", but
for the library call, it's shown in "message".I found:
|commit bc24d5b97673c365f19be21f83acca3c184cf1a7
|Author: Bruce Momjian <bruce@momjian.us>
|Date: Tue Aug 29 02:11:30 2006 +0000
|
| Now bind displays prepare as detail, and execute displays prepare and
| optionally bind. I re-added the "statement:" label so people will
| understand why the line is being printed (it is log_*statement
| behavior).
|
| Use single quotes for bind values, instead of double quotes, and double
| literal single quotes in bind values (and document that). I also made
| use of the DETAIL line to have much cleaner output.and:
|commit c8961bf1ce0b51019db31c5572dac18b664e02f1
|Author: Bruce Momjian <bruce@momjian.us>
|Date: Fri Aug 4 18:53:46 2006 +0000
|
| Improve logging of protocol-level prepared statements.Justin
Attachments:
0001-Conditionally-re-log-prepared-statement-during-execu.patchtext/x-diff; charset=us-asciiDownload
From 21c504144f378e9c24198476c14a32a3021cd95c Mon Sep 17 00:00:00 2001
From: Justin Pryzby <justin@telsasoft.com>
Date: Sat, 9 Feb 2019 19:20:43 -0500
Subject: [PATCH] Conditionally re-log prepared statement during execution
Now controlled by log_error_verbosity>=PGERROR_VERBOSE.
---
src/backend/tcop/postgres.c | 23 ++++++++++++++++++-----
1 file changed, 18 insertions(+), 5 deletions(-)
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 36cfd507b2..622e780d3d 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1042,7 +1042,7 @@ exec_simple_query(const char *query_string)
ereport(LOG,
(errmsg("statement: %s", query_string),
errhidestmt(true),
- errdetail_execute(parsetree_list)));
+ Log_error_verbosity>=PGERROR_VERBOSE ? errdetail_execute(parsetree_list) : 0));
was_logged = true;
}
@@ -1966,6 +1966,7 @@ exec_execute_message(const char *portal_name, long max_rows)
bool is_xact_command;
bool execute_is_fetch;
bool was_logged = false;
+ bool log_prepared;
char msec_str[32];
/* Adjust destination to tell printtup.c what to do */
@@ -2058,18 +2059,29 @@ exec_execute_message(const char *portal_name, long max_rows)
*/
execute_is_fetch = !portal->atStart;
+ /*
+ * Log "execute <unnamed>: ..." rather than just "execute <unnamed>"
+ * when using the unnamed portal and unamed perpared statements, which
+ * are used behind the scenes by PQexecParams.
+ * XXX: if anything else uses unnamed portal+unnamed prepared, then the
+ * prepared statement will be logged on every EXECUTE.
+ */
+ log_prepared = (!*portal_name && !portal->prepStmtName) ||
+ Log_error_verbosity>=PGERROR_VERBOSE;
+
/* Log immediately if dictated by log_statement */
if (check_log_statement(portal->stmts))
{
ereport(LOG,
- (errmsg("%s %s%s%s: %s",
+ (errmsg("%s %s%s%s%s%s",
execute_is_fetch ?
_("execute fetch from") :
_("execute"),
prepStmtName,
*portal_name ? "/" : "",
*portal_name ? portal_name : "",
- sourceText),
+ log_prepared ? ": " : "",
+ log_prepared ? sourceText : ""),
errhidestmt(true),
errdetail_params(portalParams)));
was_logged = true;
@@ -2150,7 +2162,7 @@ exec_execute_message(const char *portal_name, long max_rows)
break;
case 2:
ereport(LOG,
- (errmsg("duration: %s ms %s %s%s%s: %s",
+ (errmsg("duration: %s ms %s %s%s%s%s%s",
msec_str,
execute_is_fetch ?
_("execute fetch from") :
@@ -2158,7 +2170,8 @@ exec_execute_message(const char *portal_name, long max_rows)
prepStmtName,
*portal_name ? "/" : "",
*portal_name ? portal_name : "",
- sourceText),
+ log_prepared ? ": " : "",
+ log_prepared ? sourceText : ""),
errhidestmt(true),
errdetail_params(portalParams)));
break;
--
2.12.2
On Fri, Feb 15, 2019 at 08:57:04AM -0600, Justin Pryzby wrote:
I propose that the prepared statement associated with an EXECUTE should be
included in log "DETAIL" only when log_error_verbosity=VERBOSE, for both SQL
EXECUTE and PQexecPrepared (if at all). I'd like to be able to continue
logging DETAIL (including bind parameters), so want like to avoid setting
"TERSE" just to avoid redundant messages. (It occurs to me that the GUC should
probably stick to its existing documented behavior rather than be extended,
which suggests that the duplicitive portions of the logs should simply be
removed, rather than conditionalized. Let me know what you think).
I'm attaching a v2 patch which avoids repeated logging of PREPARE, rather than
making such logs conditional on log_error_verbosity=VERBOSE, since
log_error_verbosity is documented to control whether these are output:
DETAIL/HINT/QUERY/CONTEXT/SQLSTATE.
For SQL EXECUTE, excluding "detail" seems reasonable (perhaps for
log_error_verbosity<VERBOSE). But for PQexecPrepared, the
v1 patch made log_error_verbosity also control the "message" output, which is
outside the scope of its documented behavior.
|message | execute qq: PREPARE qq AS SELECT $1
|detail | parameters: $1 = '3'
https://www.postgresql.org/docs/current/runtime-config-logging.html
|Controls the amount of detail written in the server log for each message that
|is logged. Valid values are TERSE, DEFAULT, and VERBOSE, each adding more
|fields to displayed messages. TERSE excludes the logging of DETAIL, HINT,
|QUERY, and CONTEXT error information. VERBOSE output includes the SQLSTATE
|error code (see also Appendix A) and the source code file name, function name,
|and line number that generated the error. Only superusers can change this
|setting.
As I mentioned in my original message, it seems odd that for SQL EXECUTE, the
PREPARE is shown in "detail", but for the library call, it's shown in
"message". This patch resolves that inconsistency by showing it in neither.
Attachments:
v2-0001-Avoid-repetitive-log-of-PREPARE-during-EXECUTE-of.patchtext/x-diff; charset=us-asciiDownload
From d60957d9cd1108f389dde0125fadee71a96b4229 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <justin@telsasoft.com>
Date: Sat, 9 Feb 2019 19:20:43 -0500
Subject: [PATCH v2] Avoid repetitive log of PREPARE during EXECUTE of prepared
statements
---
src/backend/tcop/postgres.c | 13 +++++--------
1 file changed, 5 insertions(+), 8 deletions(-)
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 8b4d94c9a1..dac5362c81 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1041,8 +1041,7 @@ exec_simple_query(const char *query_string)
{
ereport(LOG,
(errmsg("statement: %s", query_string),
- errhidestmt(true),
- errdetail_execute(parsetree_list)));
+ errhidestmt(true)));
was_logged = true;
}
@@ -2062,14 +2061,13 @@ exec_execute_message(const char *portal_name, long max_rows)
if (check_log_statement(portal->stmts))
{
ereport(LOG,
- (errmsg("%s %s%s%s: %s",
+ (errmsg("%s %s%s%s",
execute_is_fetch ?
_("execute fetch from") :
_("execute"),
prepStmtName,
*portal_name ? "/" : "",
- *portal_name ? portal_name : "",
- sourceText),
+ *portal_name ? portal_name : ""),
errhidestmt(true),
errdetail_params(portalParams)));
was_logged = true;
@@ -2150,15 +2148,14 @@ exec_execute_message(const char *portal_name, long max_rows)
break;
case 2:
ereport(LOG,
- (errmsg("duration: %s ms %s %s%s%s: %s",
+ (errmsg("duration: %s ms %s %s%s%s",
msec_str,
execute_is_fetch ?
_("execute fetch from") :
_("execute"),
prepStmtName,
*portal_name ? "/" : "",
- *portal_name ? portal_name : "",
- sourceText),
+ *portal_name ? portal_name : ""),
errhidestmt(true),
errdetail_params(portalParams)));
break;
--
2.12.2
Hello Justin,
On 27.02.2019 21:06, Justin Pryzby wrote:
I'm attaching a v2 patch which avoids repeated logging of PREPARE, rather than
making such logs conditional on log_error_verbosity=VERBOSE, since
log_error_verbosity is documented to control whether these are output:
DETAIL/HINT/QUERY/CONTEXT/SQLSTATE.
I looked the patch. I got interesting result with different parameters.
With log_statement='all' and log_min_duration_statement='0' I get:
=# execute test_ins(3);
LOG: statement: execute test_ins(3);
LOG: duration: 17.283 ms
But with log_statement='none' and log_min_duration_statement='0' I get:
=# execute test_ins(3);
LOG: duration: 8.439 ms statement: execute test_ins(3);
DETAIL: prepare: prepare test_ins (int) as
insert into test values ($1);
Is it intended? In the second result I got the query details.
--
Arthur Zakirov
Postgres Professional: http://www.postgrespro.com
Russian Postgres Company
On Mon, Mar 04, 2019 at 06:53:31PM +0300, Arthur Zakirov wrote:
Hello Justin,
On 27.02.2019 21:06, Justin Pryzby wrote:
I'm attaching a v2 patch which avoids repeated logging of PREPARE, rather than
making such logs conditional on log_error_verbosity=VERBOSE, since
log_error_verbosity is documented to control whether these are output:
DETAIL/HINT/QUERY/CONTEXT/SQLSTATE.I looked the patch. I got interesting result with different parameters.
But with log_statement='none' and log_min_duration_statement='0' I get:
=# execute test_ins(3);
LOG: duration: 8.439 ms statement: execute test_ins(3);
DETAIL: prepare: prepare test_ins (int) as
insert into test values ($1);Is it intended? In the second result I got the query details.
It wasn't intentional. Find attached v3 patch which handles that case,
by removing the 2nd call to errdetail_execute() ; since it's otherwise unused,
so remove that function entirely.
|postgres=# execute test_ins(3);
|2019-03-04 11:56:15.997 EST [4044] LOG: duration: 0.637 ms statement: execute test_ins(3);
I also fixed a 2nd behavior using library call pqExecPrepared with
log_min_duration_statement=0.
It was logging:
|LOG: duration: 0.264 ms statement: SELECT 1; PREPARE q AS SELECT $1
|LOG: duration: 0.027 ms bind q: SELECT 1; PREPARE q AS SELECT $1
|DETAIL: parameters: $1 = '1'
|LOG: duration: 0.006 ms execute q: SELECT 1; PREPARE q AS SELECT $1
|DETAIL: parameters: $1 = '1'
But now logs:
PGPORT=5679 PGHOST=/tmp PYTHONPATH=../PyGreSQL/build/lib.linux-x86_64-2.7/ python2.7 -c "import pg; d=pg.DB('postgres'); d.query('SET client_min_messages=error; SET log_error_verbosity=default; SET log_min_duration_statement=0; SET log_statement=\"none\"'); d.query('SELECT 1; PREPARE q AS SELECT \$1'); d.query_prepared('q',[1])"
|LOG: duration: 0.479 ms statement: SELECT 1; PREPARE q AS SELECT $1
|LOG: duration: 0.045 ms bind q
|DETAIL: parameters: $1 = '1'
|LOG: duration: 0.008 ms execute q
|DETAIL: parameters: $1 = '1'
Thanks for reviewing. I'm also interested in discussion about whether this
change is undesirable for someone else for some reason ? For me, the existing
output seems duplicative and "denormalized". :)
Justin
Attachments:
v3-0001-Avoid-repetitive-log-of-PREPARE-during-EXECUTE-of.patchtext/x-diff; charset=us-asciiDownload
From c04f2fe815a55babe6a9bdd53421d74fc283094b Mon Sep 17 00:00:00 2001
From: Justin Pryzby <justin@telsasoft.com>
Date: Sat, 9 Feb 2019 19:20:43 -0500
Subject: [PATCH v3] Avoid repetitive log of PREPARE during EXECUTE of prepared
statements
---
src/backend/tcop/postgres.c | 54 +++++++--------------------------------------
1 file changed, 8 insertions(+), 46 deletions(-)
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 8b4d94c9a1..f348475ea3 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -182,7 +182,6 @@ static int ReadCommand(StringInfo inBuf);
static void forbidden_in_wal_sender(char firstchar);
static List *pg_rewrite_query(Query *query);
static bool check_log_statement(List *stmt_list);
-static int errdetail_execute(List *raw_parsetree_list);
static int errdetail_params(ParamListInfo params);
static int errdetail_abort(void);
static int errdetail_recovery_conflict(void);
@@ -1041,8 +1040,7 @@ exec_simple_query(const char *query_string)
{
ereport(LOG,
(errmsg("statement: %s", query_string),
- errhidestmt(true),
- errdetail_execute(parsetree_list)));
+ errhidestmt(true)));
was_logged = true;
}
@@ -1292,8 +1290,7 @@ exec_simple_query(const char *query_string)
ereport(LOG,
(errmsg("duration: %s ms statement: %s",
msec_str, query_string),
- errhidestmt(true),
- errdetail_execute(parsetree_list)));
+ errhidestmt(true)));
break;
}
@@ -1929,12 +1926,11 @@ exec_bind_message(StringInfo input_message)
break;
case 2:
ereport(LOG,
- (errmsg("duration: %s ms bind %s%s%s: %s",
+ (errmsg("duration: %s ms bind %s%s%s",
msec_str,
*stmt_name ? stmt_name : "<unnamed>",
*portal_name ? "/" : "",
- *portal_name ? portal_name : "",
- psrc->query_string),
+ *portal_name ? portal_name : ""),
errhidestmt(true),
errdetail_params(params)));
break;
@@ -2062,14 +2058,13 @@ exec_execute_message(const char *portal_name, long max_rows)
if (check_log_statement(portal->stmts))
{
ereport(LOG,
- (errmsg("%s %s%s%s: %s",
+ (errmsg("%s %s%s%s",
execute_is_fetch ?
_("execute fetch from") :
_("execute"),
prepStmtName,
*portal_name ? "/" : "",
- *portal_name ? portal_name : "",
- sourceText),
+ *portal_name ? portal_name : ""),
errhidestmt(true),
errdetail_params(portalParams)));
was_logged = true;
@@ -2150,15 +2145,14 @@ exec_execute_message(const char *portal_name, long max_rows)
break;
case 2:
ereport(LOG,
- (errmsg("duration: %s ms %s %s%s%s: %s",
+ (errmsg("duration: %s ms %s %s%s%s",
msec_str,
execute_is_fetch ?
_("execute fetch from") :
_("execute"),
prepStmtName,
*portal_name ? "/" : "",
- *portal_name ? portal_name : "",
- sourceText),
+ *portal_name ? portal_name : ""),
errhidestmt(true),
errdetail_params(portalParams)));
break;
@@ -2267,38 +2261,6 @@ check_log_duration(char *msec_str, bool was_logged)
}
/*
- * errdetail_execute
- *
- * Add an errdetail() line showing the query referenced by an EXECUTE, if any.
- * The argument is the raw parsetree list.
- */
-static int
-errdetail_execute(List *raw_parsetree_list)
-{
- ListCell *parsetree_item;
-
- foreach(parsetree_item, raw_parsetree_list)
- {
- RawStmt *parsetree = lfirst_node(RawStmt, parsetree_item);
-
- if (IsA(parsetree->stmt, ExecuteStmt))
- {
- ExecuteStmt *stmt = (ExecuteStmt *) parsetree->stmt;
- PreparedStatement *pstmt;
-
- pstmt = FetchPreparedStatement(stmt->name, false);
- if (pstmt)
- {
- errdetail("prepare: %s", pstmt->plansource->query_string);
- return 0;
- }
- }
- }
-
- return 0;
-}
-
-/*
* errdetail_params
*
* Add an errdetail() line showing bind-parameter data, if available.
--
2.12.2
On 04.03.2019 21:31, Justin Pryzby wrote:
It wasn't intentional. Find attached v3 patch which handles that case,
by removing the 2nd call to errdetail_execute() ; since it's otherwise unused,
so remove that function entirely.
Thank you.
Thanks for reviewing. I'm also interested in discussion about whether this
change is undesirable for someone else for some reason ? For me, the existing
output seems duplicative and "denormalized". :)
I perfectly understand your use case. I agree, it is duplicated. But I
think some people may want to see it at every EXECUTE, if they don't
want to grep for the prepared statement body which was logged earlier.
I think it would be good to give possibility to configure this behavior.
At first version of your patch you relied on log_error_verbosity GUC.
I'm not sure that this variables is suitable for configuring visibility
of prepared statement body in logs, because it sets more general
behavior. Maybe it would be better to introduce some new GUC variable if
the community don't mind.
--
Arthur Zakirov
Postgres Professional: http://www.postgrespro.com
Russian Postgres Company
Hi Justin,
On 3/5/19 2:30 PM, Arthur Zakirov wrote:
On 04.03.2019 21:31, Justin Pryzby wrote:
It wasn't intentional.� Find attached v3 patch which handles that case,
by removing the 2nd call to errdetail_execute() ; since it's otherwise
unused,
so remove that function entirely.Thank you.
Thanks for reviewing.� I'm also interested in discussion about whether
this
change is undesirable for someone else for some reason ?� For me, the
existing
output seems duplicative and "denormalized".� :)I perfectly understand your use case. I agree, it is duplicated. But I
think some people may want to see it at every EXECUTE, if they don't
want to grep for the prepared statement body which was logged earlier.I think it would be good to give possibility to configure this behavior.
At first version of your patch you relied on log_error_verbosity GUC.
I'm not sure that this variables is suitable for configuring visibility
of prepared statement body in logs, because it sets more general
behavior. Maybe it would be better to introduce some new GUC variable if
the community don't mind.
Thoughts on this?
Regards,
--
-David
david@pgmasters.net
Hi,
On Wed, Mar 20, 2019 at 02:46:00PM +0400, David Steele wrote:
I perfectly understand your use case. I agree, it is duplicated. But I
think some people may want to see it at every EXECUTE, if they don't want
to grep for the prepared statement body which was logged earlier.I think it would be good to give possibility to configure this behavior.
At first version of your patch you relied on log_error_verbosity GUC. I'm
not sure that this variables is suitable for configuring visibility of
prepared statement body in logs, because it sets more general behavior.
Maybe it would be better to introduce some new GUC variable if the
community don't mind.Thoughts on this?
I'm happy to make the behavior configurable, but I'm having trouble believing
many people would want a GUC added for this. But I'd be interested to hear
input on whether it should be configurable, or whether the original "verbose"
logging is desirable to anyone.
This is mostly tangential, but since writing the original patch, I considered
the possibility of a logging GUC which is scales better than log_* booleans:
/messages/by-id/20190316122422.GR6030@telsasoft.com
If that idea were desirable, there could be a logging_bit to enable verbose
logging of prepared statements.
Justin
On 2019-Mar-04, Justin Pryzby wrote:
Thanks for reviewing. I'm also interested in discussion about whether this
change is undesirable for someone else for some reason ? For me, the existing
output seems duplicative and "denormalized". :)
Some digging turned up that the function you're removing was added by
commit 893632be4e17. The commit message mentions output for testlibpq3,
so I ran that against a patched server. With log_min_duration_statement=0
I get this, which looks good:
2019-04-04 14:59:15.529 -03 [31723] LOG: duration: 0.108 ms statement: SET search_path = testlibpq3
2019-04-04 14:59:15.530 -03 [31723] LOG: duration: 0.303 ms parse <unnamed>: SELECT * FROM test1 WHERE t = $1
2019-04-04 14:59:15.530 -03 [31723] LOG: duration: 0.231 ms bind <unnamed>
2019-04-04 14:59:15.530 -03 [31723] DETAIL: parameters: $1 = 'joe''s place'
2019-04-04 14:59:15.530 -03 [31723] LOG: duration: 0.016 ms execute <unnamed>
2019-04-04 14:59:15.530 -03 [31723] DETAIL: parameters: $1 = 'joe''s place'
2019-04-04 14:59:15.530 -03 [31723] LOG: duration: 0.096 ms parse <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
2019-04-04 14:59:15.530 -03 [31723] LOG: duration: 0.053 ms bind <unnamed>
2019-04-04 14:59:15.530 -03 [31723] DETAIL: parameters: $1 = '2'
2019-04-04 14:59:15.530 -03 [31723] LOG: duration: 0.007 ms execute <unnamed>
2019-04-04 14:59:15.530 -03 [31723] DETAIL: parameters: $1 = '2'
An unpatched server emits this:
2019-04-04 15:03:01.176 -03 [1165] LOG: duration: 0.163 ms statement: SET search_path = testlibpq3
2019-04-04 15:03:01.176 -03 [1165] LOG: duration: 0.475 ms parse <unnamed>: SELECT * FROM test1 WHERE t = $1
2019-04-04 15:03:01.177 -03 [1165] LOG: duration: 0.403 ms bind <unnamed>: SELECT * FROM test1 WHERE t = $1
2019-04-04 15:03:01.177 -03 [1165] DETAIL: parameters: $1 = 'joe''s place'
2019-04-04 15:03:01.177 -03 [1165] LOG: duration: 0.028 ms execute <unnamed>: SELECT * FROM test1 WHERE t = $1
2019-04-04 15:03:01.177 -03 [1165] DETAIL: parameters: $1 = 'joe''s place'
2019-04-04 15:03:01.177 -03 [1165] LOG: duration: 0.177 ms parse <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
2019-04-04 15:03:01.177 -03 [1165] LOG: duration: 0.096 ms bind <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
2019-04-04 15:03:01.177 -03 [1165] DETAIL: parameters: $1 = '2'
2019-04-04 15:03:01.177 -03 [1165] LOG: duration: 0.014 ms execute <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
2019-04-04 15:03:01.177 -03 [1165] DETAIL: parameters: $1 = '2'
Note that with your patch we no longer get the statement in the "bind" and
"execute" lines, which seems good; that was far too noisy.
However, turning duration logging off and using log_statement=all, this is what
I get:
2019-04-04 14:58:42.564 -03 [31685] LOG: statement: SET search_path = testlibpq3
2019-04-04 14:58:42.565 -03 [31685] LOG: execute <unnamed>
2019-04-04 14:58:42.565 -03 [31685] DETAIL: parameters: $1 = 'joe''s place'
2019-04-04 14:58:42.565 -03 [31685] LOG: execute <unnamed>
2019-04-04 14:58:42.565 -03 [31685] DETAIL: parameters: $1 = '2'
which does not look good -- the statement is nowhere to be seen. The commit
message quotes this as desirable output:
LOG: statement: execute <unnamed>: SELECT * FROM test1 WHERE t = $1
DETAIL: parameters: $1 = 'joe''s place'
LOG: statement: execute <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
DETAIL: parameters: $1 = '2'
which is approximately what I get with an unpatched server:
2019-04-04 15:04:25.718 -03 [1235] LOG: statement: SET search_path = testlibpq3
2019-04-04 15:04:25.719 -03 [1235] LOG: execute <unnamed>: SELECT * FROM test1 WHERE t = $1
2019-04-04 15:04:25.719 -03 [1235] DETAIL: parameters: $1 = 'joe''s place'
2019-04-04 15:04:25.720 -03 [1235] LOG: execute <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
2019-04-04 15:04:25.720 -03 [1235] DETAIL: parameters: $1 = '2'
So I think this needs a bit more work.
--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On 2019-Apr-04, Alvaro Herrera wrote:
However, turning duration logging off and using log_statement=all, this is what
I get:2019-04-04 14:58:42.564 -03 [31685] LOG: statement: SET search_path = testlibpq3
2019-04-04 14:58:42.565 -03 [31685] LOG: execute <unnamed>
2019-04-04 14:58:42.565 -03 [31685] DETAIL: parameters: $1 = 'joe''s place'
2019-04-04 14:58:42.565 -03 [31685] LOG: execute <unnamed>
2019-04-04 14:58:42.565 -03 [31685] DETAIL: parameters: $1 = '2'
With this patch (pretty much equivalent to reinstanting the
errdetail_execute for that line),
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index dbc7b797c6e..fd73d5e9951 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2056,7 +2056,6 @@ exec_execute_message(const char *portal_name, long max_rows)
prepStmtName,
*portal_name ? "/" : "",
*portal_name ? portal_name : ""),
- errhidestmt(true),
errdetail_params(portalParams)));
was_logged = true;
}I get what seems to be pretty much what is wanted for this case:
2019-04-04 15:18:16.817 -03 [4559] LOG: statement: SET search_path = testlibpq3
2019-04-04 15:18:16.819 -03 [4559] LOG: execute <unnamed>
2019-04-04 15:18:16.819 -03 [4559] DETAIL: parameters: $1 = 'joe''s place'
2019-04-04 15:18:16.819 -03 [4559] STATEMENT: SELECT * FROM test1 WHERE t = $1
2019-04-04 15:18:16.820 -03 [4559] LOG: execute <unnamed>
2019-04-04 15:18:16.820 -03 [4559] DETAIL: parameters: $1 = '2'
2019-04-04 15:18:16.820 -03 [4559] STATEMENT: SELECT * FROM test1 WHERE i = $1::int4
However, by setting both log_statement=all and
log_min_duration_statement=0 and that patch (I also added %l to
log_line_prefix), I get this:
2019-04-04 15:23:45 -03 [5208-1] LOG: statement: SET search_path = testlibpq3
2019-04-04 15:23:45 -03 [5208-2] LOG: duration: 0.441 ms
2019-04-04 15:23:45 -03 [5208-3] LOG: duration: 1.127 ms parse <unnamed>: SELECT * FROM test1 WHERE t = $1
2019-04-04 15:23:45 -03 [5208-4] LOG: duration: 0.789 ms bind <unnamed>
2019-04-04 15:23:45 -03 [5208-5] DETAIL: parameters: $1 = 'joe''s place'
2019-04-04 15:23:45 -03 [5208-6] LOG: execute <unnamed>
2019-04-04 15:23:45 -03 [5208-7] DETAIL: parameters: $1 = 'joe''s place'
2019-04-04 15:23:45 -03 [5208-8] STATEMENT: SELECT * FROM test1 WHERE t = $1
2019-04-04 15:23:45 -03 [5208-9] LOG: duration: 0.088 ms
2019-04-04 15:23:45 -03 [5208-10] LOG: duration: 0.363 ms parse <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
2019-04-04 15:23:45 -03 [5208-11] LOG: duration: 0.206 ms bind <unnamed>
2019-04-04 15:23:45 -03 [5208-12] DETAIL: parameters: $1 = '2'
2019-04-04 15:23:45 -03 [5208-13] LOG: execute <unnamed>
2019-04-04 15:23:45 -03 [5208-14] DETAIL: parameters: $1 = '2'
2019-04-04 15:23:45 -03 [5208-15] STATEMENT: SELECT * FROM test1 WHERE i = $1::int4
2019-04-04 15:23:45 -03 [5208-16] LOG: duration: 0.053 ms
Note that line 5208-8 is duplicative of 5208-3.
I think we could improve on this by setting a "logged" flag in the
portal; if the Parse logs the statement, then don't include the
statement in further lines, otherwise do.
--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On 2019-Apr-04, Alvaro Herrera wrote:
I think we could improve on this by setting a "logged" flag in the
portal; if the Parse logs the statement, then don't include the
statement in further lines, otherwise do.
Also: I think such a flag could help the case of a query that takes
long enough to execute to exceed the log_min_duration_statement, but not
long enough to parse. Right now, log_min_duration_statement=500 shows
2019-04-04 15:59:39 -03 [6353-1] LOG: duration: 2002.298 ms execute <unnamed>
2019-04-04 15:59:39 -03 [6353-2] DETAIL: parameters: $1 = 'joe''s place'
if I change the testlibpq3 query to be
"SELECT * FROM test1 WHERE t = $1 and pg_sleep(1) is not null",
Also, if you parse once and bind/execute many times, IMO the statement
should be logged exactly once. I think you could that with the flag I
propose.
--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On Thu, Apr 04, 2019 at 03:07:04PM -0300, Alvaro Herrera wrote:
which does not look good -- the statement is nowhere to be seen. The commit
message quotes this as desirable output:
Good catch.
Unnamed statements sent behind the scenes by pqExecParams weren't being logged.
I specifically handled unnamed statements in my v1 patch, and tested that in
20190215145704.GW30291@telsasoft.com, but for some reason dropped that logic in
v2, which was intended to only remove behavior conditional on
log_error_verbosity.
Previous patches also never logged pqPrepare with named prepared statements
(unnamed prepared statements were handled in v1 and SQL PREPARE was handled as
a simple statement).
On Thu, Apr 04, 2019 at 03:26:30PM -0300, Alvaro Herrera wrote:
With this patch (pretty much equivalent to reinstanting the
errdetail_execute for that line),
That means the text of the prepared statement is duplicated for each execute,
which is what we're trying to avoid, no ?
Attached patch promotes message to LOG in exec_parse_message. Parse is a
protocol-layer message, and I think it's used by (only) pqPrepare and
pqExecParams.
testlibpq3 now shows:
|LOG: parse <unnamed>: SELECT * FROM test1 WHERE t = $1
|LOG: execute <unnamed>
|DETAIL: parameters: $1 = 'joe''s place'
|LOG: parse <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
|LOG: execute <unnamed>
|DETAIL: parameters: $1 = '2'
Compare unpatched v11.2 , the text of the prepared statement was shown in
"parse" phase rather than in each execute:
|LOG: execute <unnamed>: SELECT * FROM test1 WHERE t = $1
|DETAIL: parameters: $1 = 'joe''s place'
|LOG: execute <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
|DETAIL: parameters: $1 = '2'
Justin
Attachments:
v4-0001-Avoid-repetitive-log-of-PREPARE-during-EXECUTE-of.patchtext/x-diff; charset=us-asciiDownload
From 0826f7f90eb8f169244140a22db0bbbcb0d2b269 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <justin@telsasoft.com>
Date: Sat, 9 Feb 2019 19:20:43 -0500
Subject: [PATCH v4] Avoid repetitive log of PREPARE during EXECUTE of prepared
statements
---
src/backend/tcop/postgres.c | 70 ++++++++++++---------------------------------
1 file changed, 18 insertions(+), 52 deletions(-)
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 44a59e1..348343c 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -182,7 +182,6 @@ static int ReadCommand(StringInfo inBuf);
static void forbidden_in_wal_sender(char firstchar);
static List *pg_rewrite_query(Query *query);
static bool check_log_statement(List *stmt_list);
-static int errdetail_execute(List *raw_parsetree_list);
static int errdetail_params(ParamListInfo params);
static int errdetail_abort(void);
static int errdetail_recovery_conflict(void);
@@ -1041,8 +1040,7 @@ exec_simple_query(const char *query_string)
{
ereport(LOG,
(errmsg("statement: %s", query_string),
- errhidestmt(true),
- errdetail_execute(parsetree_list)));
+ errhidestmt(true)));
was_logged = true;
}
@@ -1292,8 +1290,7 @@ exec_simple_query(const char *query_string)
ereport(LOG,
(errmsg("duration: %s ms statement: %s",
msec_str, query_string),
- errhidestmt(true),
- errdetail_execute(parsetree_list)));
+ errhidestmt(true)));
break;
}
@@ -1326,6 +1323,7 @@ exec_parse_message(const char *query_string, /* string to execute */
bool is_named;
bool save_log_statement_stats = log_statement_stats;
char msec_str[32];
+ bool was_logged = false;
/*
* Report query to various monitoring facilities.
@@ -1339,11 +1337,6 @@ exec_parse_message(const char *query_string, /* string to execute */
if (save_log_statement_stats)
ResetUsage();
- ereport(DEBUG2,
- (errmsg("parse %s: %s",
- *stmt_name ? stmt_name : "<unnamed>",
- query_string)));
-
/*
* Start up a transaction command so we can run parse analysis etc. (Note
* that this will normally change current memory context.) Nothing happens
@@ -1404,6 +1397,14 @@ exec_parse_message(const char *query_string, /* string to execute */
Query *query;
bool snapshot_set = false;
+ if (check_log_statement(parsetree_list)) {
+ ereport( LOG, // else log as DEBUG2 ?
+ (errmsg("parse %s: %s",
+ *stmt_name ? stmt_name : "<unnamed>",
+ query_string)));
+ was_logged = true;
+ }
+
raw_parse_tree = linitial_node(RawStmt, parsetree_list);
/*
@@ -1544,7 +1545,7 @@ exec_parse_message(const char *query_string, /* string to execute */
/*
* Emit duration logging if appropriate.
*/
- switch (check_log_duration(msec_str, false))
+ switch (check_log_duration(msec_str, was_logged))
{
case 1:
ereport(LOG,
@@ -1920,12 +1921,11 @@ exec_bind_message(StringInfo input_message)
break;
case 2:
ereport(LOG,
- (errmsg("duration: %s ms bind %s%s%s: %s",
+ (errmsg("duration: %s ms bind %s%s%s",
msec_str,
*stmt_name ? stmt_name : "<unnamed>",
*portal_name ? "/" : "",
- *portal_name ? portal_name : "",
- psrc->query_string),
+ *portal_name ? portal_name : ""),
errhidestmt(true),
errdetail_params(params)));
break;
@@ -2053,14 +2053,13 @@ exec_execute_message(const char *portal_name, long max_rows)
if (check_log_statement(portal->stmts))
{
ereport(LOG,
- (errmsg("%s %s%s%s: %s",
+ (errmsg("%s %s%s%s",
execute_is_fetch ?
_("execute fetch from") :
_("execute"),
prepStmtName,
*portal_name ? "/" : "",
- *portal_name ? portal_name : "",
- sourceText),
+ *portal_name ? portal_name : ""),
errhidestmt(true),
errdetail_params(portalParams)));
was_logged = true;
@@ -2141,15 +2140,14 @@ exec_execute_message(const char *portal_name, long max_rows)
break;
case 2:
ereport(LOG,
- (errmsg("duration: %s ms %s %s%s%s: %s",
+ (errmsg("duration: %s ms %s %s%s%s",
msec_str,
execute_is_fetch ?
_("execute fetch from") :
_("execute"),
prepStmtName,
*portal_name ? "/" : "",
- *portal_name ? portal_name : "",
- sourceText),
+ *portal_name ? portal_name : ""),
errhidestmt(true),
errdetail_params(portalParams)));
break;
@@ -2260,38 +2258,6 @@ check_log_duration(char *msec_str, bool was_logged)
}
/*
- * errdetail_execute
- *
- * Add an errdetail() line showing the query referenced by an EXECUTE, if any.
- * The argument is the raw parsetree list.
- */
-static int
-errdetail_execute(List *raw_parsetree_list)
-{
- ListCell *parsetree_item;
-
- foreach(parsetree_item, raw_parsetree_list)
- {
- RawStmt *parsetree = lfirst_node(RawStmt, parsetree_item);
-
- if (IsA(parsetree->stmt, ExecuteStmt))
- {
- ExecuteStmt *stmt = (ExecuteStmt *) parsetree->stmt;
- PreparedStatement *pstmt;
-
- pstmt = FetchPreparedStatement(stmt->name, false);
- if (pstmt)
- {
- errdetail("prepare: %s", pstmt->plansource->query_string);
- return 0;
- }
- }
- }
-
- return 0;
-}
-
-/*
* errdetail_params
*
* Add an errdetail() line showing bind-parameter data, if available.
--
2.1.4
Import Notes
Reply to msg id not found: 20190404182630.GA4305@alvherre.pgsql20190404180704.GA31569@alvherre.pgsql | Resolved by subject fallback
Hi,
On 2019-04-04 16:01:26 -0300, Alvaro Herrera wrote:
Also, if you parse once and bind/execute many times, IMO the statement
should be logged exactly once. I think you could that with the flag I
propose.
I'm not actually sure I buy this. Consider e.g. log analysis for
workloads with long-running connections. If most statements are just
already prepared statements - pretty common in higher throughput apps -
the query will suddenly be either far away in the logfile (thereby
requiring pretty expensive analysis to figure out the corresponding
statement) or even in a different logfile due to rotation.
I'm sympathetic to the desire to reduce log volume, but I'm fearful this
would make log analysis much harder. Searching through many gigabytes
just to find the query text of the statement being executed over and
over doesn't sound great.
I think deduplicating the logging between bind and execute has less of
that hazard.
- Andres
Hi,
Thanks both for thinking about this.
On Fri, Apr 05, 2019 at 06:16:38PM -0700, Andres Freund wrote:
On 2019-04-04 16:01:26 -0300, Alvaro Herrera wrote:
Also, if you parse once and bind/execute many times, IMO the statement
should be logged exactly once. I think you could that with the flag I
propose.
I think deduplicating the logging between bind and execute has less of
that hazard.
Do you mean the bind parameters, which are only duplicated in the case of
log_min_duration_statement ?
I actually implemented that, using Alvaro's suggestion of a flag in the Portal,
and decided that if duration is exceeded, for bind or execute, then it's likely
desirable to log the params, even if it's duplicitive. Since I've been using
log_statement=all, and not log_min_duration_statement, I don't have a strong
opinion about it.
Perhaps you're right (and perhaps I should switch to
log_min_duration_statement). I'll tentately plan to withdraw the patch.
Thanks,
Justin
On 2019-Apr-07, Justin Pryzby wrote:
[...] Since I've been using log_statement=all, and not
log_min_duration_statement, I don't have a strong opinion about it.
Ah, so your plan for this in production is to use the sample-based
logging facilities, I see! Did you get Adrien a beer already?
--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services