Re: query logging of prepared statements

On 2019-Apr-04, Alvaro Herrera wrote:

> However, turning duration logging off and using log_statement=all, this is what
> I get:
>
> 2019-04-04 14:58:42.564 -03 [31685] LOG: statement: SET search_path = testlibpq3
> 2019-04-04 14:58:42.565 -03 [31685] LOG: execute <unnamed>
> 2019-04-04 14:58:42.565 -03 [31685] DETAIL: parameters: $1 = 'joe''s place'
> 2019-04-04 14:58:42.565 -03 [31685] LOG: execute <unnamed>
> 2019-04-04 14:58:42.565 -03 [31685] DETAIL: parameters: $1 = '2'

With this patch (pretty much equivalent to reinstanting the
errdetail_execute for that line),

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index dbc7b797c6e..fd73d5e9951 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2056,7 +2056,6 @@ exec_execute_message(const char *portal_name, long max_rows)
prepStmtName,
*portal_name ? "/" : "",
*portal_name ? portal_name : ""),
- errhidestmt(true),
errdetail_params(portalParams)));
was_logged = true;
}

I get what seems to be pretty much what is wanted for this case:

2019-04-04 15:18:16.817 -03 [4559] LOG: statement: SET search_path = testlibpq3
2019-04-04 15:18:16.819 -03 [4559] LOG: execute <unnamed>
2019-04-04 15:18:16.819 -03 [4559] DETAIL: parameters: $1 = 'joe''s place'
2019-04-04 15:18:16.819 -03 [4559] STATEMENT: SELECT * FROM test1 WHERE t = $1
2019-04-04 15:18:16.820 -03 [4559] LOG: execute <unnamed>
2019-04-04 15:18:16.820 -03 [4559] DETAIL: parameters: $1 = '2'
2019-04-04 15:18:16.820 -03 [4559] STATEMENT: SELECT * FROM test1 WHERE i = $1::int4

However, by setting both log_statement=all and
log_min_duration_statement=0 and that patch (I also added %l to
log_line_prefix), I get this:

2019-04-04 15:23:45 -03 [5208-1] LOG: statement: SET search_path = testlibpq3
2019-04-04 15:23:45 -03 [5208-2] LOG: duration: 0.441 ms
2019-04-04 15:23:45 -03 [5208-3] LOG: duration: 1.127 ms parse <unnamed>: SELECT * FROM test1 WHERE t = $1
2019-04-04 15:23:45 -03 [5208-4] LOG: duration: 0.789 ms bind <unnamed>
2019-04-04 15:23:45 -03 [5208-5] DETAIL: parameters: $1 = 'joe''s place'
2019-04-04 15:23:45 -03 [5208-6] LOG: execute <unnamed>
2019-04-04 15:23:45 -03 [5208-7] DETAIL: parameters: $1 = 'joe''s place'
2019-04-04 15:23:45 -03 [5208-8] STATEMENT: SELECT * FROM test1 WHERE t = $1
2019-04-04 15:23:45 -03 [5208-9] LOG: duration: 0.088 ms
2019-04-04 15:23:45 -03 [5208-10] LOG: duration: 0.363 ms parse <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
2019-04-04 15:23:45 -03 [5208-11] LOG: duration: 0.206 ms bind <unnamed>
2019-04-04 15:23:45 -03 [5208-12] DETAIL: parameters: $1 = '2'
2019-04-04 15:23:45 -03 [5208-13] LOG: execute <unnamed>
2019-04-04 15:23:45 -03 [5208-14] DETAIL: parameters: $1 = '2'
2019-04-04 15:23:45 -03 [5208-15] STATEMENT: SELECT * FROM test1 WHERE i = $1::int4
2019-04-04 15:23:45 -03 [5208-16] LOG: duration: 0.053 ms

Note that line 5208-8 is duplicative of 5208-3.

I think we could improve on this by setting a "logged" flag in the
portal; if the Parse logs the statement, then don't include the
statement in further lines, otherwise do.

--
Álvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services