Date: Sat, 9 Feb 2019 19:57:08 -0600
From: Justin Pryzby <pryzby@telsasoft.com>
To: pgsql-general@postgresql.org
Cc: Bruce Momjian <bruce@momjian.us>
Subject: Re: query logging of prepared statements
Message-ID: <20190210015707.GQ31721@telsasoft.com>
References: <20190208132953.GF29720@telsasoft.com>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="hoZxPH4CaxYzWscb"
Content-Disposition: inline
In-Reply-To: <20190208132953.GF29720@telsasoft.com>
User-Agent: Mutt/1.5.23 (2014-03-12)
Precedence: bulk


--hoZxPH4CaxYzWscb
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

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

--hoZxPH4CaxYzWscb
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="0001-Conditionally-re-log-prepared-statement-during-execu.patch"

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


--hoZxPH4CaxYzWscb--