pg.ddx.io  pgsql-hackers@postgresql.org mailing list archive  

help / color / mirror / Atom feed
From: Alvaro Herrera <alvherre@2ndquadrant.com>
To: Justin Pryzby <pryzby@telsasoft.com>
Cc: Arthur Zakirov <a.zakirov@postgrespro.ru>
Cc: pgsql-hackers@postgresql.org
Subject: Re: query logging of prepared statements
Date: Thu, 4 Apr 2019 15:26:30 -0300
Message-ID: <20190404182630.GA4305@alvherre.pgsql> (raw)
In-Reply-To: <20190404180704.GA31569@alvherre.pgsql>

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),


inline patch 1: src/backend/tcop/postgres.c (+0/-1 lines) download inline-1.patchdiff --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





view thread (16+ messages)  latest in thread

Message-ID: <20190404182630.GA4305@alvherre.pgsql>
Permalink:  ../20190404182630.GA4305@alvherre.pgsql/
Also on:    postgresql.org/message-id/20190404182630.GA4305@alvherre.pgsql

 ·  · 

reply
Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Reply to all the recipients using the --to and --cc options:
  reply via email

  To: pgsql-hackers@postgresql.org
  Cc: alvherre@2ndquadrant.com, pryzby@telsasoft.com, a.zakirov@postgrespro.ru
  Subject: Re: query logging of prepared statements
  In-Reply-To: <20190404182630.GA4305@alvherre.pgsql>

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox