Feedback-ID: i1ff147bf:Fastmail
From: =?utf-8?Q?Dagfinn_Ilmari_Manns=C3=A5ker?= <ilmari@ilmari.org>
To: Michael Paquier <michael@paquier.xyz>
Cc: pgsql-hackers@lists.postgresql.org
Subject: Re: Logging query parmeters in auto_explain
References: <87ee09mohb.fsf@wibble.ilmari.org> <Yp8D4kb2qZnhNAWJ@paquier.xyz>
Date: Tue, 07 Jun 2022 12:18:52 +0100
In-Reply-To: <Yp8D4kb2qZnhNAWJ@paquier.xyz> (Michael Paquier's message of
	"Tue, 7 Jun 2022 16:53:06 +0900")
Message-ID: <8735ggn2lf.fsf@wibble.ilmari.org>
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/27.1 (gnu/linux)
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="=-=-="
Archived-At: 
 <https://www.postgresql.org/message-id/8735ggn2lf.fsf%40wibble.ilmari.org>
Precedence: bulk

--=-=-=
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 8bit

Michael Paquier <michael@paquier.xyz> writes:

> On Tue, May 31, 2022 at 09:33:20PM +0100, Dagfinn Ilmari Mannsåker wrote:
>> Here's a patch that adds a corresponding
>> auto_explain.log_parameter_max_length config setting, which controls the
>> "Query Parameters" node in the logged plan.  Just like in core, the
>> default is -1, which logs the parameters in full, and 0 disables
>> parameter logging, while any other value truncates each parameter to
>> that many bytes.
>
> With a behavior similar to the in-core log_parameter_max_length, this
> looks rather sane to me.  This is consistent with the assumptions of
> errdetail_params().

That was the intention, yes.

> +$node->append_conf('postgresql.conf', "auto_explain.log_parameter_max_length = -1");
> Nit.  You don't need this change in the TAP test, as this is the
> default value to log everything.

Point, fixed in the attached v2. I've also added a test that truncation
and disabling works.

- ilmari


--=-=-=
Content-Type: text/x-diff
Content-Disposition: inline;
 filename=v2-0001-Log-query-parameters-in-auto_explain.patch

From 4ba1f1353413b2348228d98d7f102620d6c2e060 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Dagfinn=20Ilmari=20Manns=C3=A5ker?= <ilmari@ilmari.org>
Date: Tue, 31 May 2022 21:12:12 +0100
Subject: [PATCH v2] Log query parameters in auto_explain

Add an auto_explain.log_parameter_max_length config setting, similar
to the corresponding core setting, that controls the inclusion of
query parameters in the logged explain output.
---
 contrib/auto_explain/auto_explain.c        | 15 +++++++
 contrib/auto_explain/t/001_auto_explain.pl | 46 +++++++++++++++++++++-
 doc/src/sgml/auto-explain.sgml             | 19 +++++++++
 src/backend/commands/explain.c             | 22 +++++++++++
 src/include/commands/explain.h             |  1 +
 5 files changed, 101 insertions(+), 2 deletions(-)

diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index c9a0d947c8..1ba7536879 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -19,12 +19,14 @@
 #include "common/pg_prng.h"
 #include "executor/instrument.h"
 #include "jit/jit.h"
+#include "nodes/params.h"
 #include "utils/guc.h"
 
 PG_MODULE_MAGIC;
 
 /* GUC variables */
 static int	auto_explain_log_min_duration = -1; /* msec or -1 */
+static int	auto_explain_log_parameter_max_length = -1; /* bytes or -1 */
 static bool auto_explain_log_analyze = false;
 static bool auto_explain_log_verbose = false;
 static bool auto_explain_log_buffers = false;
@@ -105,6 +107,18 @@ _PG_init(void)
 							NULL,
 							NULL);
 
+	DefineCustomIntVariable("auto_explain.log_parameter_max_length",
+							"Sets the maximum length of query parameters to log.",
+							"Zero logs no query parameters, -1 logs them in full.",
+							&auto_explain_log_parameter_max_length,
+							-1,
+							-1, INT_MAX,
+							PGC_SUSET,
+							GUC_UNIT_BYTE,
+							NULL,
+							NULL,
+							NULL);
+
 	DefineCustomBoolVariable("auto_explain.log_analyze",
 							 "Use EXPLAIN ANALYZE for plan logging.",
 							 NULL,
@@ -389,6 +403,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
 
 			ExplainBeginOutput(es);
 			ExplainQueryText(es, queryDesc);
+			ExplainQueryParameters(es, queryDesc->params, auto_explain_log_parameter_max_length);
 			ExplainPrintPlan(es, queryDesc);
 			if (es->analyze && auto_explain_log_triggers)
 				ExplainPrintTriggers(es, queryDesc);
diff --git a/contrib/auto_explain/t/001_auto_explain.pl b/contrib/auto_explain/t/001_auto_explain.pl
index 82e4d9d15c..518ba16826 100644
--- a/contrib/auto_explain/t/001_auto_explain.pl
+++ b/contrib/auto_explain/t/001_auto_explain.pl
@@ -19,14 +19,26 @@
 # run a couple of queries
 $node->safe_psql("postgres", "SELECT * FROM pg_class;");
 $node->safe_psql("postgres",
-	"SELECT * FROM pg_proc WHERE proname = 'int4pl';");
+	q{PREPARE get_proc(name) AS SELECT * FROM pg_proc WHERE proname = $1; EXECUTE get_proc('int4pl');});
 
 # emit some json too
 $node->append_conf('postgresql.conf', "auto_explain.log_format = json");
 $node->reload;
 $node->safe_psql("postgres", "SELECT * FROM pg_proc;");
 $node->safe_psql("postgres",
-	"SELECT * FROM pg_class WHERE relname = 'pg_class';");
+	q{PREPARE get_class(name) AS SELECT * FROM pg_class WHERE relname = $1; EXECUTE get_class('pg_class');});
+
+# check that logged parameters can be truncated
+$node->append_conf('postgresql.conf', "auto_explain.log_parameter_max_length = 3");
+$node->reload;
+$node->safe_psql("postgres",
+	q{PREPARE get_type(name) AS SELECT * FROM pg_type WHERE typname = $1; EXECUTE get_type('float8');});
+
+# check that parameter logging can be disabled
+$node->append_conf('postgresql.conf', "auto_explain.log_parameter_max_length = 0");
+$node->reload;
+$node->safe_psql("postgres",
+	q{PREPARE get_type(name) AS SELECT * FROM pg_type WHERE typname = $1; EXECUTE get_type('int8');});
 
 $node->stop('fast');
 
@@ -34,6 +46,16 @@
 
 my $log_contents = slurp_file($log);
 
+like(
+	$log_contents,
+	qr/Query Text: SELECT \* FROM pg_class;/,
+	"query text logged, text mode");
+
+like(
+	$log_contents,
+	qr/Query Parameters: \$1 = 'int4pl'/,
+	"query parameters logged, text mode");
+
 like(
 	$log_contents,
 	qr/Seq Scan on pg_class/,
@@ -44,6 +66,16 @@
 	qr/Index Scan using pg_proc_proname_args_nsp_index on pg_proc/,
 	"index scan logged, text mode");
 
+like(
+	$log_contents,
+	qr/"Query Text": "SELECT \* FROM pg_proc;"/,
+	"query text logged, json mode");
+
+like(
+	$log_contents,
+	qr/"Query Parameters": "\$1 = 'pg_class'"/,
+	"query parameters logged, json mode");
+
 like(
 	$log_contents,
 	qr/"Node Type": "Seq Scan"[^}]*"Relation Name": "pg_proc"/s,
@@ -54,4 +86,14 @@
 	qr/"Node Type": "Index Scan"[^}]*"Index Name": "pg_class_relname_nsp_index"/s,
 	"index scan logged, json mode");
 
+like(
+	$log_contents,
+	qr/"Query Parameters": "\$1 = 'flo\.\.\.'"/,
+	"query parameters truncated");
+
+unlike(
+	$log_contents,
+	qr/"Query Parameters": "\$1 = 'int8'"/,
+	"query parameters truncated");
+
 done_testing();
diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml
index 30e35a714a..a033c9c685 100644
--- a/doc/src/sgml/auto-explain.sgml
+++ b/doc/src/sgml/auto-explain.sgml
@@ -63,6 +63,25 @@
     </listitem>
    </varlistentry>
 
+   <varlistentry>
+    <term>
+     <varname>auto_explain.log_parameter_max_length</varname> (<type>integer</type>)
+     <indexterm>
+      <primary><varname>auto_explain.log_parameter_max_length</varname> configuration parameter</primary>
+     </indexterm>
+    </term>
+    <listitem>
+     <para>
+      <varname>auto_explain.log_parameter_max_length</varname> controls the
+      logging of query parameter values.  A value of<literal>-1</literal> (the
+      default) logs the parameter values in full. <literal>0</literal> disables
+      logging of parameter values.  A value greater than zero truncates each
+      parameter value to that many bytes. Only superusers can change this
+      setting.
+     </para>
+    </listitem>
+   </varlistentry>
+
    <varlistentry>
     <term>
      <varname>auto_explain.log_analyze</varname> (<type>boolean</type>)
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 5d1f7089da..8584e3585d 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -972,6 +972,28 @@ ExplainQueryText(ExplainState *es, QueryDesc *queryDesc)
 		ExplainPropertyText("Query Text", queryDesc->sourceText, es);
 }
 
+/*
+ * ExplainQueryParameters -
+ *	  add a "Query Parameters" node that describes the parameters of the query,
+ *	  if any
+ *
+ * The caller should have set up the options fields of *es, as well as
+ * initializing the output buffer es->str.
+ *
+ */
+void
+ExplainQueryParameters(ExplainState *es, ParamListInfo params, int maxlen)
+{
+	char	   *str;
+
+	if (params == NULL || params->numParams == 0 || maxlen == 0)
+		return;
+
+	str = BuildParamLogString(params, NULL, maxlen);
+	if (str && str[0] != '\0')
+		ExplainPropertyText("Query Parameters", str, es);
+}
+
 /*
  * report_triggers -
  *		report execution stats for a single relation's triggers
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 666977fb1f..9ebde089ae 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -99,6 +99,7 @@ extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);
 extern void ExplainPrintJITSummary(ExplainState *es, QueryDesc *queryDesc);
 
 extern void ExplainQueryText(ExplainState *es, QueryDesc *queryDesc);
+extern void ExplainQueryParameters(ExplainState *es, ParamListInfo params, int maxlen);
 
 extern void ExplainBeginOutput(ExplainState *es);
 extern void ExplainEndOutput(ExplainState *es);
-- 
2.30.2


--=-=-=--