Date: Thu, 4 Apr 2019 16:26:13 -0500
From: Justin Pryzby <pryzby@telsasoft.com>
To: Alvaro Herrera <alvherre@2ndquadrant.com>
Cc: Arthur Zakirov <a.zakirov@postgrespro.ru>, pgsql-hackers@postgresql.org
Subject: Re: query logging of prepared statements
Message-ID: <20190404212613.GA16096@telsasoft.com>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="7AUc2qLy4jB3hD7Z"
Content-Disposition: inline
In-Reply-To: <20190404182630.GA4305@alvherre.pgsql>
 <20190404180704.GA31569@alvherre.pgsql>
User-Agent: Mutt/1.5.23 (2014-03-12)
Precedence: bulk


--7AUc2qLy4jB3hD7Z
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

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

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

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

---
 src/backend/tcop/postgres.c | 70 ++++++++++++---------------------------------
 1 file changed, 18 insertions(+), 52 deletions(-)

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 44a59e1..348343c 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;
 	}
 
@@ -1326,6 +1323,7 @@ exec_parse_message(const char *query_string,	/* string to execute */
 	bool		is_named;
 	bool		save_log_statement_stats = log_statement_stats;
 	char		msec_str[32];
+	bool		was_logged = false;
 
 	/*
 	 * Report query to various monitoring facilities.
@@ -1339,11 +1337,6 @@ exec_parse_message(const char *query_string,	/* string to execute */
 	if (save_log_statement_stats)
 		ResetUsage();
 
-	ereport(DEBUG2,
-			(errmsg("parse %s: %s",
-					*stmt_name ? stmt_name : "<unnamed>",
-					query_string)));
-
 	/*
 	 * Start up a transaction command so we can run parse analysis etc. (Note
 	 * that this will normally change current memory context.) Nothing happens
@@ -1404,6 +1397,14 @@ exec_parse_message(const char *query_string,	/* string to execute */
 		Query	   *query;
 		bool		snapshot_set = false;
 
+		if (check_log_statement(parsetree_list)) {
+			ereport( LOG, // else log as DEBUG2 ?
+				(errmsg("parse %s: %s",
+						*stmt_name ? stmt_name : "<unnamed>",
+						query_string)));
+			was_logged = true;
+		}
+
 		raw_parse_tree = linitial_node(RawStmt, parsetree_list);
 
 		/*
@@ -1544,7 +1545,7 @@ exec_parse_message(const char *query_string,	/* string to execute */
 	/*
 	 * Emit duration logging if appropriate.
 	 */
-	switch (check_log_duration(msec_str, false))
+	switch (check_log_duration(msec_str, was_logged))
 	{
 		case 1:
 			ereport(LOG,
@@ -1920,12 +1921,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;
@@ -2053,14 +2053,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;
@@ -2141,15 +2140,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;
@@ -2260,38 +2258,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.1.4


--7AUc2qLy4jB3hD7Z--