Re: query logging of prepared statements

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.
https://www.postgresql.org/message-id/20190208132953.GF29720%40telsasoft.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(at)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(at)momjian(dot)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(at)momjian(dot)us>
> |Date: Fri Aug 4 18:53:46 2006 +0000
> |
> | Improve logging of protocol-level prepared statements.
>
> Justin