Re: Logging query parmeters in auto_explain

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

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