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.GW30291@telsasoft.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