query logging of prepared statements

From: Justin Pryzby <pryzby(at)telsasoft(dot)com>
To: pgsql-general(at)postgresql(dot)org
Cc: Bruce Momjian <bruce(at)momjian(dot)us>
Subject: query logging of prepared statements
Date: 2019-02-08 13:29:53
Message-ID: 20190208132953.GF29720@telsasoft.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general pgsql-hackers

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

Responses

Browse pgsql-general by date

  From Date Subject
Next Message PegoraroF10 2019-02-08 21:11:33 Re: Server goes to Recovery Mode when run a SQL
Previous Message Eugene Podshivalov 2019-02-07 22:44:35 Full text search parser dictionary

Browse pgsql-hackers by date

  From Date Subject
Next Message Raúl Marín 2019-02-08 13:30:51 Re: [PATCH] pgbench tap tests fail if the path contains a perl special character
Previous Message Tomas Vondra 2019-02-08 13:27:59 Re: performance issue in remove_from_unowned_list()