Date: Fri, 8 Feb 2019 07:29:53 -0600
From: Justin Pryzby <pryzby@telsasoft.com>
To: pgsql-general@postgresql.org
Cc: Bruce Momjian <bruce@momjian.us>
Subject: query logging of prepared statements
Message-ID: <20190208132953.GF29720@telsasoft.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
User-Agent: Mutt/1.5.23 (2014-03-12)
Precedence: bulk

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