On Mon, Jun 27, 2022 at 12:27:57PM +0100, Dagfinn Ilmari Mannsåker wrote: > I forgot to mention, I also changed the order of the query and > parameters, so that they can more naturally be left out when no changes > are needed.
I can see that, and I have added $node as an extra parameter of the routine. After putting my hands on that, it also felt a bit unnatural to do the refactoring of the tests and the addition of the new GUC in the same patch, so I have split things as the attached. The amount of coverage is still the same but it makes the integration of the feature easier to follow. -- Michael
From 17899218c72b43794832bb55c0e785bbdf3e97ea Mon Sep 17 00:00:00 2001
From: Michael Paquier <mich...@paquier.xyz>
Date: Tue, 28 Jun 2022 16:37:29 +0900
Subject: [PATCH v5 1/2] Refactor TAP test of auto_explain
---
contrib/auto_explain/t/001_auto_explain.pl | 90 ++++++++++++++++++----
1 file changed, 74 insertions(+), 16 deletions(-)
diff --git a/contrib/auto_explain/t/001_auto_explain.pl b/contrib/auto_explain/t/001_auto_explain.pl
index 82e4d9d15c..1523ac2d46 100644
--- a/contrib/auto_explain/t/001_auto_explain.pl
+++ b/contrib/auto_explain/t/001_auto_explain.pl
@@ -8,6 +8,42 @@ use PostgreSQL::Test::Cluster;
use PostgreSQL::Test::Utils;
use Test::More;
+# Runs the specified query and returns the emitted server log.
+# If any parameters are specified, these are set in postgresql.conf,
+# and reset after the query is run.
+sub query_log
+{
+ my ($node, $sql, $params) = @_;
+ $params ||= {};
+
+ if (keys %$params)
+ {
+ for my $key (keys %$params)
+ {
+ $node->append_conf('postgresql.conf', "$key = $params->{$key}\n");
+ }
+ $node->reload;
+ }
+
+ my $log = $node->logfile();
+ my $offset = -s $log;
+
+ $node->safe_psql("postgres", $sql);
+
+ my $log_contents = slurp_file($log, $offset);
+
+ if (keys %$params)
+ {
+ for my $key (keys %$params)
+ {
+ $node->adjust_conf('postgresql.conf', $key, undef);
+ }
+ $node->reload;
+ }
+
+ return $log_contents;
+}
+
my $node = PostgreSQL::Test::Cluster->new('main');
$node->init;
$node->append_conf('postgresql.conf',
@@ -16,39 +52,61 @@ $node->append_conf('postgresql.conf', "auto_explain.log_min_duration = 0");
$node->append_conf('postgresql.conf', "auto_explain.log_analyze = on");
$node->start;
-# run a couple of queries
-$node->safe_psql("postgres", "SELECT * FROM pg_class;");
-$node->safe_psql("postgres",
- "SELECT * FROM pg_proc WHERE proname = 'int4pl';");
+# Simple query.
+my $log_contents = query_log($node, "SELECT * FROM pg_class;");
-# 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';");
-
-$node->stop('fast');
-
-my $log = $node->logfile();
-
-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/Seq Scan on pg_class/,
"sequential scan logged, text mode");
+# Prepared query.
+$log_contents = query_log($node,
+ q{PREPARE get_proc(name) AS SELECT * FROM pg_proc WHERE proname = $1; EXECUTE get_proc('int4pl');}
+);
+
+like(
+ $log_contents,
+ 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/Index Scan using pg_proc_proname_args_nsp_index on pg_proc/,
"index scan logged, text mode");
+# JSON format.
+$log_contents = query_log(
+ $node,
+ "SELECT * FROM pg_proc;",
+ { "auto_explain.log_format" => "json" });
+
+like(
+ $log_contents,
+ qr/"Query Text": "SELECT \* FROM pg_proc;"/,
+ "query text logged, json mode");
+
like(
$log_contents,
qr/"Node Type": "Seq Scan"[^}]*"Relation Name": "pg_proc"/s,
"sequential scan logged, json mode");
+# Prepared query in JSON format.
+$log_contents = query_log(
+ $node,
+ q{PREPARE get_class(name) AS SELECT * FROM pg_class WHERE relname = $1; EXECUTE get_class('pg_class');},
+ { "auto_explain.log_format" => "json" });
+
+like(
+ $log_contents,
+ qr/"Query Text": "PREPARE get_class\(name\) AS SELECT \* FROM pg_class WHERE relname = \$1;"/,
+ "prepared query text logged, json mode");
+
like(
$log_contents,
qr/"Node Type": "Index Scan"[^}]*"Index Name": "pg_class_relname_nsp_index"/s,
--
2.36.1
From 2d9e496f8ccd9a1b14c785609f27dd94c4cfd5a9 Mon Sep 17 00:00:00 2001
From: Michael Paquier <mich...@paquier.xyz>
Date: Tue, 28 Jun 2022 16:49:26 +0900
Subject: [PATCH v5 2/2] 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.
Also adjust the tests to only look at the relevant parts of the log
for each query, and reset the GUCs after each test.
---
src/include/commands/explain.h | 1 +
src/backend/commands/explain.c | 22 ++++++++++
doc/src/sgml/auto-explain.sgml | 19 +++++++++
contrib/auto_explain/auto_explain.c | 15 +++++++
contrib/auto_explain/t/001_auto_explain.pl | 48 ++++++++++++++++++++++
5 files changed, 105 insertions(+)
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);
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/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 @@ 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/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 1523ac2d46..1d952fb54d 100644
--- 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,
--
2.36.1
signature.asc
Description: PGP signature
