Date: Mon, 4 Mar 2019 12:31:50 -0600
From: Justin Pryzby <pryzby@telsasoft.com>
To: Arthur Zakirov <a.zakirov@postgrespro.ru>
Cc: pgsql-hackers@postgresql.org
Subject: Re: query logging of prepared statements
Message-ID: <20190304183150.GK29584@telsasoft.com>
References: <20190208132953.GF29720@telsasoft.com>
 <20190215145704.GW30291@telsasoft.com>
 <20190227180653.GF28750@telsasoft.com>
 <70868e0d-2a29-36c8-e3e2-f54a56804bc4@postgrespro.ru>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="+pHx0qQiF2pBVqBT"
Content-Disposition: inline
In-Reply-To: <70868e0d-2a29-36c8-e3e2-f54a56804bc4@postgrespro.ru>
User-Agent: Mutt/1.5.23 (2014-03-12)
Precedence: bulk


--+pHx0qQiF2pBVqBT
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

On Mon, Mar 04, 2019 at 06:53:31PM +0300, Arthur Zakirov wrote:
> Hello Justin,
> 
> On 27.02.2019 21:06, Justin Pryzby wrote:
> >I'm attaching a v2 patch which avoids repeated logging of PREPARE, rather than
> >making such logs conditional on log_error_verbosity=VERBOSE, since
> >log_error_verbosity is documented to control whether these are output:
> >DETAIL/HINT/QUERY/CONTEXT/SQLSTATE.
> I looked the patch. I got interesting result with different parameters.
> 
> But with log_statement='none' and log_min_duration_statement='0' I get:
> 
> =# execute test_ins(3);
> LOG:  duration: 8.439 ms  statement: execute test_ins(3);
> DETAIL:  prepare: prepare test_ins (int) as
> insert into test values ($1);
> 
> Is it intended? In the second result I got the query details.

It wasn't intentional.  Find attached v3 patch which handles that case,
by removing the 2nd call to errdetail_execute() ; since it's otherwise unused,
so remove that function entirely.

|postgres=# execute test_ins(3);
|2019-03-04 11:56:15.997 EST [4044] LOG:  duration: 0.637 ms  statement: execute test_ins(3);

I also fixed a 2nd behavior using library call pqExecPrepared with
log_min_duration_statement=0.

It was logging:
|LOG:  duration: 0.264 ms  statement: SELECT 1; PREPARE q AS SELECT $1
|LOG:  duration: 0.027 ms  bind q: SELECT 1; PREPARE q AS SELECT $1
|DETAIL:  parameters: $1 = '1'
|LOG:  duration: 0.006 ms  execute q: SELECT 1; PREPARE q AS SELECT $1
|DETAIL:  parameters: $1 = '1'

But now logs:

PGPORT=5679 PGHOST=/tmp PYTHONPATH=../PyGreSQL/build/lib.linux-x86_64-2.7/ python2.7 -c "import pg; d=pg.DB('postgres'); d.query('SET client_min_messages=error; SET log_error_verbosity=default; SET log_min_duration_statement=0; SET log_statement=\"none\"'); d.query('SELECT 1; PREPARE q AS SELECT \$1'); d.query_prepared('q',[1])"
|LOG:  duration: 0.479 ms  statement: SELECT 1; PREPARE q AS SELECT $1
|LOG:  duration: 0.045 ms  bind q
|DETAIL:  parameters: $1 = '1'
|LOG:  duration: 0.008 ms  execute q
|DETAIL:  parameters: $1 = '1'

Thanks for reviewing.  I'm also interested in discussion about whether this
change is undesirable for someone else for some reason ?  For me, the existing
output seems duplicative and "denormalized".  :)

Justin

--+pHx0qQiF2pBVqBT
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="v3-0001-Avoid-repetitive-log-of-PREPARE-during-EXECUTE-of.patch"

From c04f2fe815a55babe6a9bdd53421d74fc283094b Mon Sep 17 00:00:00 2001
From: Justin Pryzby <justin@telsasoft.com>
Date: Sat, 9 Feb 2019 19:20:43 -0500
Subject: [PATCH v3] Avoid repetitive log of PREPARE during EXECUTE of prepared
 statements

---
 src/backend/tcop/postgres.c | 54 +++++++--------------------------------------
 1 file changed, 8 insertions(+), 46 deletions(-)

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 8b4d94c9a1..f348475ea3 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -182,7 +182,6 @@ static int	ReadCommand(StringInfo inBuf);
 static void forbidden_in_wal_sender(char firstchar);
 static List *pg_rewrite_query(Query *query);
 static bool check_log_statement(List *stmt_list);
-static int	errdetail_execute(List *raw_parsetree_list);
 static int	errdetail_params(ParamListInfo params);
 static int	errdetail_abort(void);
 static int	errdetail_recovery_conflict(void);
@@ -1041,8 +1040,7 @@ exec_simple_query(const char *query_string)
 	{
 		ereport(LOG,
 				(errmsg("statement: %s", query_string),
-				 errhidestmt(true),
-				 errdetail_execute(parsetree_list)));
+				 errhidestmt(true)));
 		was_logged = true;
 	}
 
@@ -1292,8 +1290,7 @@ exec_simple_query(const char *query_string)
 			ereport(LOG,
 					(errmsg("duration: %s ms  statement: %s",
 							msec_str, query_string),
-					 errhidestmt(true),
-					 errdetail_execute(parsetree_list)));
+					 errhidestmt(true)));
 			break;
 	}
 
@@ -1929,12 +1926,11 @@ exec_bind_message(StringInfo input_message)
 			break;
 		case 2:
 			ereport(LOG,
-					(errmsg("duration: %s ms  bind %s%s%s: %s",
+					(errmsg("duration: %s ms  bind %s%s%s",
 							msec_str,
 							*stmt_name ? stmt_name : "<unnamed>",
 							*portal_name ? "/" : "",
-							*portal_name ? portal_name : "",
-							psrc->query_string),
+							*portal_name ? portal_name : ""),
 					 errhidestmt(true),
 					 errdetail_params(params)));
 			break;
@@ -2062,14 +2058,13 @@ exec_execute_message(const char *portal_name, long max_rows)
 	if (check_log_statement(portal->stmts))
 	{
 		ereport(LOG,
-				(errmsg("%s %s%s%s: %s",
+				(errmsg("%s %s%s%s",
 						execute_is_fetch ?
 						_("execute fetch from") :
 						_("execute"),
 						prepStmtName,
 						*portal_name ? "/" : "",
-						*portal_name ? portal_name : "",
-						sourceText),
+						*portal_name ? portal_name : ""),
 				 errhidestmt(true),
 				 errdetail_params(portalParams)));
 		was_logged = true;
@@ -2150,15 +2145,14 @@ exec_execute_message(const char *portal_name, long max_rows)
 			break;
 		case 2:
 			ereport(LOG,
-					(errmsg("duration: %s ms  %s %s%s%s: %s",
+					(errmsg("duration: %s ms  %s %s%s%s",
 							msec_str,
 							execute_is_fetch ?
 							_("execute fetch from") :
 							_("execute"),
 							prepStmtName,
 							*portal_name ? "/" : "",
-							*portal_name ? portal_name : "",
-							sourceText),
+							*portal_name ? portal_name : ""),
 					 errhidestmt(true),
 					 errdetail_params(portalParams)));
 			break;
@@ -2267,38 +2261,6 @@ check_log_duration(char *msec_str, bool was_logged)
 }
 
 /*
- * errdetail_execute
- *
- * Add an errdetail() line showing the query referenced by an EXECUTE, if any.
- * The argument is the raw parsetree list.
- */
-static int
-errdetail_execute(List *raw_parsetree_list)
-{
-	ListCell   *parsetree_item;
-
-	foreach(parsetree_item, raw_parsetree_list)
-	{
-		RawStmt    *parsetree = lfirst_node(RawStmt, parsetree_item);
-
-		if (IsA(parsetree->stmt, ExecuteStmt))
-		{
-			ExecuteStmt *stmt = (ExecuteStmt *) parsetree->stmt;
-			PreparedStatement *pstmt;
-
-			pstmt = FetchPreparedStatement(stmt->name, false);
-			if (pstmt)
-			{
-				errdetail("prepare: %s", pstmt->plansource->query_string);
-				return 0;
-			}
-		}
-	}
-
-	return 0;
-}
-
-/*
  * errdetail_params
  *
  * Add an errdetail() line showing bind-parameter data, if available.
-- 
2.12.2


--+pHx0qQiF2pBVqBT--