From: Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
To: Michael Paquier <michael@paquier.xyz>
Cc: pgsql-hackers@lists.postgresql.org
Subject: Re: Logging query parmeters in auto_explain
Date: Tue, 07 Jun 2022 12:18:52 +0100
Message-ID: <8735ggn2lf.fsf@wibble.ilmari.org> (raw)
In-Reply-To: <Yp8D4kb2qZnhNAWJ@paquier.xyz>
References: <87ee09mohb.fsf@wibble.ilmari.org>
<Yp8D4kb2qZnhNAWJ@paquier.xyz>
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
Attachments:v2-0001-Log-query-parameters-in-auto_explain.patch (text/x-diff, 7.5K) download
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.cindex 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.plindex 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.sgmlindex 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.cindex 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.hindex 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
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-hackers@postgresql.org
Cc: ilmari@ilmari.org, michael@paquier.xyz, pgsql-hackers@lists.postgresql.org
Subject: Re: Logging query parmeters in auto_explain
In-Reply-To: <8735ggn2lf.fsf@wibble.ilmari.org>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox