Date: Thu, 4 Apr 2019 15:26:30 -0300
From: Alvaro Herrera <alvherre@2ndquadrant.com>
To: Justin Pryzby <pryzby@telsasoft.com>
Cc: Arthur Zakirov <a.zakirov@postgrespro.ru>, pgsql-hackers@postgresql.org
Subject: Re: query logging of prepared statements
Message-ID: <20190404182630.GA4305@alvherre.pgsql>
MIME-Version: 1.0
Content-Type: text/plain; charset=iso-8859-1
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: <20190404180704.GA31569@alvherre.pgsql>
User-Agent: Mutt/1.9.4 (2018-02-28)
Precedence: bulk

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