autho_explain: Add GUC to log query parameters

auto_explain.log_parameter_max_length is a new GUC part of the
extension, similar to the corresponding core setting, that controls the
inclusion of query parameters in the logged explain output.

More tests are added to check the behavior of this new parameter: when
parameters logged in full (the default of -1), when disabled (value of
0) and when partially truncated (value different than the two others).

Author: Dagfinn Ilmari Mannsåker
Discussion: https://postgr.es/m/87ee09mohb.fsf@wibble.ilmari.org

diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index c9a0d947c8314755432c450fc1aacf8243994eec..1ba7536879d2da54c20acebcce28cd22d8c6919a 100644 (file)
--- 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 1523ac2d46e2bc68efe3d350147866886b94b012..1d952fb54d363fc12128d2aaba9cb936024a83de 100644 (file)
--- a/contrib/auto_explain/t/001_auto_explain.pl
+++ b/contrib/auto_explain/t/001_auto_explain.pl
@@ -60,6 +60,11 @@ like(
    qr/Query Text: SELECT \* FROM pg_class;/,
    "query text logged, text mode");
 
+unlike(
+   $log_contents,
+   qr/Query Parameters:/,
+   "no query parameters logged when none, text mode");
+
 like(
    $log_contents,
    qr/Seq Scan on pg_class/,
@@ -75,11 +80,49 @@ like(
    qr/Query Text: PREPARE get_proc\(name\) AS SELECT \* FROM pg_proc WHERE proname = \$1;/,
    "prepared query text logged, text mode");
 
+like(
+   $log_contents,
+   qr/Query Parameters: \$1 = 'int4pl'/,
+   "query parameters logged, text mode");
+
 like(
    $log_contents,
    qr/Index Scan using pg_proc_proname_args_nsp_index on pg_proc/,
    "index scan logged, text mode");
 
+
+# Prepared query with truncated parameters.
+$log_contents = query_log(
+   $node,
+   q{PREPARE get_type(name) AS SELECT * FROM pg_type WHERE typname = $1; EXECUTE get_type('float8');},
+   { "auto_explain.log_parameter_max_length" => 3 });
+
+like(
+   $log_contents,
+   qr/Query Text: PREPARE get_type\(name\) AS SELECT \* FROM pg_type WHERE typname = \$1;/,
+   "prepared query text logged, text mode");
+
+like(
+   $log_contents,
+   qr/Query Parameters: \$1 = 'flo\.\.\.'/,
+   "query parameters truncated, text mode");
+
+# Prepared query with parameter logging disabled.
+$log_contents = query_log(
+   $node,
+   q{PREPARE get_type(name) AS SELECT * FROM pg_type WHERE typname = $1; EXECUTE get_type('float8');},
+   { "auto_explain.log_parameter_max_length" => 0 });
+
+like(
+   $log_contents,
+   qr/Query Text: PREPARE get_type\(name\) AS SELECT \* FROM pg_type WHERE typname = \$1;/,
+   "prepared query text logged, text mode");
+
+unlike(
+   $log_contents,
+   qr/Query Parameters:/,
+   "query parameters not logged when disabled, text mode");
+
 # JSON format.
 $log_contents = query_log(
    $node,
@@ -91,6 +134,11 @@ like(
    qr/"Query Text": "SELECT \* FROM pg_proc;"/,
    "query text logged, json mode");
 
+unlike(
+   $log_contents,
+   qr/"Query Parameters":/,
+   "query parameters not logged when none, json mode");
+
 like(
    $log_contents,
    qr/"Node Type": "Seq Scan"[^}]*"Relation Name": "pg_proc"/s,

diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml
index 30e35a714a5f6c92d46cc72803d179f54f1104b8..394fec94e88efcc70a1090c82d88602fe1b54859 100644 (file)
--- a/doc/src/sgml/auto-explain.sgml
+++ b/doc/src/sgml/auto-explain.sgml
@@ -63,6 +63,25 @@ LOAD 'auto_explain';
     </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 5d1f7089daf2238502c5afaf366891219f8ebef1..e29c2ae206ff4e10356f1b9f184f93d9c621c702 100644 (file)
--- 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
+ *
+ * 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;
+
+   /* This check is consistent with errdetail_params() */
+   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 666977fb1f8b86b012f17c8fede5545f00fefceb..9ebde089aedd47bf2be185bbdecef76c7c0b2e19 100644 (file)
--- 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);