Hi hackers,
Inspired by a question on IRC, I noticed that while the core statement
logging system gained the option to log statement parameters in PG 13,
auto_explain was left out.
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.
- ilmari
>From 24a31273475f26b3174a6e2178d0121f5e23b5f5 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Dagfinn=20Ilmari=20Manns=C3=A5ker?= <ilm...@ilmari.org>
Date: Tue, 31 May 2022 21:12:12 +0100
Subject: [PATCH] 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 | 25 ++++++++++++++++++++--
doc/src/sgml/auto-explain.sgml | 19 ++++++++++++++++
src/backend/commands/explain.c | 22 +++++++++++++++++++
src/include/commands/explain.h | 1 +
5 files changed, 80 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..ac57c8d6bf 100644
--- a/contrib/auto_explain/t/001_auto_explain.pl
+++ b/contrib/auto_explain/t/001_auto_explain.pl
@@ -13,20 +13,21 @@
$node->append_conf('postgresql.conf',
"shared_preload_libraries = 'auto_explain'");
$node->append_conf('postgresql.conf', "auto_explain.log_min_duration = 0");
+$node->append_conf('postgresql.conf', "auto_explain.log_parameter_max_length = -1");
$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';");
+ 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');});
$node->stop('fast');
@@ -34,6 +35,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 +55,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,
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
