Re: query logging of prepared statements

On Thu, Apr 04, 2019 at 03:07:04PM -0300, Alvaro Herrera wrote:
> which does not look good -- the statement is nowhere to be seen. The commit
> message quotes this as desirable output:

Good catch.

Unnamed statements sent behind the scenes by pqExecParams weren't being logged.

I specifically handled unnamed statements in my v1 patch, and tested that in
20190215145704(dot)GW30291(at)telsasoft(dot)com, but for some reason dropped that logic in
v2, which was intended to only remove behavior conditional on
log_error_verbosity.

Previous patches also never logged pqPrepare with named prepared statements
(unnamed prepared statements were handled in v1 and SQL PREPARE was handled as
a simple statement).

On Thu, Apr 04, 2019 at 03:26:30PM -0300, Alvaro Herrera wrote:
> With this patch (pretty much equivalent to reinstanting the
> errdetail_execute for that line),

That means the text of the prepared statement is duplicated for each execute,
which is what we're trying to avoid, no ?

Attached patch promotes message to LOG in exec_parse_message. Parse is a
protocol-layer message, and I think it's used by (only) pqPrepare and
pqExecParams.

testlibpq3 now shows:

|LOG: parse <unnamed>: SELECT * FROM test1 WHERE t = $1
|LOG: execute <unnamed>
|DETAIL: parameters: $1 = 'joe''s place'

|LOG: parse <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
|LOG: execute <unnamed>
|DETAIL: parameters: $1 = '2'

Compare unpatched v11.2 , the text of the prepared statement was shown in
"parse" phase rather than in each execute:

|LOG: execute <unnamed>: SELECT * FROM test1 WHERE t = $1
|DETAIL: parameters: $1 = 'joe''s place'

|LOG: execute <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
|DETAIL: parameters: $1 = '2'

Justin