From: Justin Pryzby <pryzby@telsasoft.com>
To: pgsql-general@postgresql.org
Cc: Bruce Momjian <bruce@momjian.us>
Subject: Re: query logging of prepared statements
Date: Sat, 9 Feb 2019 19:57:08 -0600
Message-ID: <20190210015707.GQ31721@telsasoft.com> (raw)
In-Reply-To: <20190208132953.GF29720@telsasoft.com>
References: <20190208132953.GF29720@telsasoft.com>
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.
https://www.postgresql.org/message-id/20190208132953.GF29720%40telsasoft.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
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 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
Attachments:0001-Conditionally-re-log-prepared-statement-during-execu.patch (text/x-diff, 2.8K) download
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.cindex 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
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-hackers@postgresql.org
Cc: pryzby@telsasoft.com, pgsql-general@postgresql.org, bruce@momjian.us
Subject: Re: query logging of prepared statements
In-Reply-To: <20190210015707.GQ31721@telsasoft.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox