pg.ddx.io pgsql-hackers@postgresql.org mailing list archive
help / color / mirror / Atom feedLogging query parmeters in auto_explain
15+ messages / 2 participants
[nested] [flat]
Commits from this thread:
2022-07-06 d4bfe41281 autho_explain: Add GUC to log query parameters
2022-07-01 550bc0a6c0 Refactor the TAP test of auto_explain
* Logging query parmeters in auto_explain
@ 2022-05-31 20:33 Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-06 17:12 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-07 07:53 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
0 siblings, 2 replies; 15+ messages in thread
From: Dagfinn Ilmari Mannsåker @ 2022-05-31 20:33 UTC (permalink / raw)
To: pgsql-hackers@lists.postgresql.org
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
Attachments:
0001-Log-query-parameters-in-auto_explain.patch (text/x-diff, 7.0K) download
From 24a31273475f26b3174a6e2178d0121f5e23b5f5 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] 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
* Re: Logging query parmeters in auto_explain
2022-05-31 20:33 Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
@ 2022-06-06 17:12 ` Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
1 sibling, 0 replies; 15+ messages in thread
From: Dagfinn Ilmari Mannsåker @ 2022-06-06 17:12 UTC (permalink / raw)
To: pgsql-hackers@lists.postgresql.org
Dagfinn Ilmari Mannsåker <ilmari@ilmari.org> writes:
> 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.
I've added added it to the upcoming commitfest:
https://commitfest.postgresql.org/38/3660/
- ilmari
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: Logging query parmeters in auto_explain
2022-05-31 20:33 Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
@ 2022-06-07 07:53 ` Michael Paquier <michael@paquier.xyz>
2022-06-07 11:18 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
1 sibling, 1 reply; 15+ messages in thread
From: Michael Paquier @ 2022-06-07 07:53 UTC (permalink / raw)
To: Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>; +Cc: pgsql-hackers@lists.postgresql.org
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().
+$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.
--
Michael
Attachments:
signature.asc (application/pgp-signature, 832B) download
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: Logging query parmeters in auto_explain
2022-05-31 20:33 Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-07 07:53 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
@ 2022-06-07 11:18 ` Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-09 01:44 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
0 siblings, 1 reply; 15+ messages in thread
From: Dagfinn Ilmari Mannsåker @ 2022-06-07 11:18 UTC (permalink / raw)
To: Michael Paquier <michael@paquier.xyz>; +Cc: pgsql-hackers@lists.postgresql.org
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.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
* Re: Logging query parmeters in auto_explain
2022-05-31 20:33 Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-07 07:53 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-07 11:18 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
@ 2022-06-09 01:44 ` Michael Paquier <michael@paquier.xyz>
2022-06-09 22:55 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
0 siblings, 1 reply; 15+ messages in thread
From: Michael Paquier @ 2022-06-09 01:44 UTC (permalink / raw)
To: Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>; +Cc: pgsql-hackers@lists.postgresql.org
On Tue, Jun 07, 2022 at 12:18:52PM +0100, Dagfinn Ilmari Mannsåker wrote:
> Point, fixed in the attached v2. I've also added a test that truncation
> and disabling works.
The tests are structured so as all the queries are run first, then the
full set of logs is slurped and scanned. With things like tests for
truncation, it becomes easier to have a given test overlap with
another one in terms of pattern matching, so we could silently lose
coverage. Wouldn't it be better to reorganize things so we save the
current size of the log file (as of -s $node->logfile), run one query,
and then slurp the log file based on the position saved previously?
The GUC updates had better be localized in each sub-section of the
tests, as well.
--
Michael
Attachments:
signature.asc (application/pgp-signature, 832B) download
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: Logging query parmeters in auto_explain
2022-05-31 20:33 Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-07 07:53 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-07 11:18 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-09 01:44 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
@ 2022-06-09 22:55 ` Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-14 07:50 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
0 siblings, 1 reply; 15+ messages in thread
From: Dagfinn Ilmari Mannsåker @ 2022-06-09 22:55 UTC (permalink / raw)
To: Michael Paquier <michael@paquier.xyz>; +Cc: pgsql-hackers@lists.postgresql.org
Michael Paquier <michael@paquier.xyz> writes:
> On Tue, Jun 07, 2022 at 12:18:52PM +0100, Dagfinn Ilmari Mannsåker wrote:
>> Point, fixed in the attached v2. I've also added a test that truncation
>> and disabling works.
>
> The tests are structured so as all the queries are run first, then the
> full set of logs is slurped and scanned. With things like tests for
> truncation, it becomes easier to have a given test overlap with
> another one in terms of pattern matching, so we could silently lose
> coverage. Wouldn't it be better to reorganize things so we save the
> current size of the log file (as of -s $node->logfile), run one query,
> and then slurp the log file based on the position saved previously?
> The GUC updates had better be localized in each sub-section of the
> tests, as well.
Done (and more tests added), v3 attached.
- ilmari
Attachments:
v3-0001-Log-query-parameters-in-auto_explain.patch (text/x-diff, 9.4K) download
From de3627d972f5259c9290109a6d7b08fbfa1faea2 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 v3] 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 tho reset the GUCs after each test.
---
contrib/auto_explain/auto_explain.c | 15 +++
contrib/auto_explain/t/001_auto_explain.pl | 133 ++++++++++++++++++---
doc/src/sgml/auto-explain.sgml | 19 +++
src/backend/commands/explain.c | 22 ++++
src/include/commands/explain.h | 1 +
5 files changed, 176 insertions(+), 14 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..4fa1a8457b 100644
--- a/contrib/auto_explain/t/001_auto_explain.pl
+++ b/contrib/auto_explain/t/001_auto_explain.pl
@@ -16,42 +16,147 @@
$node->append_conf('postgresql.conf', "auto_explain.log_analyze = on");
$node->start;
+sub query_log
+{
+ my ($params, $sql) = @_;
+
+ 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;
+}
+
# run a couple of queries
-$node->safe_psql("postgres", "SELECT * FROM pg_class;");
-$node->safe_psql("postgres",
- "SELECT * FROM pg_proc WHERE proname = 'int4pl';");
+my $log_contents = query_log({}, "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';");
+like(
+ $log_contents,
+ qr/Query Text: SELECT \* FROM pg_class;/,
+ "query text logged, text mode");
-$node->stop('fast');
-
-my $log = $node->logfile();
-
-my $log_contents = slurp_file($log);
+unlike(
+ $log_contents,
+ qr/Query Parameters:/,
+ "no query parameters logged when none, text mode");
like(
$log_contents,
qr/Seq Scan on pg_class/,
"sequential scan logged, text mode");
+# with parameters
+$log_contents = query_log({},
+ 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/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");
+# check that logged parameters can be truncated
+$log_contents = query_log(
+ { "auto_explain.log_parameter_max_length" => 3 },
+ q{PREPARE get_type(name) AS SELECT * FROM pg_type WHERE typname = $1; EXECUTE get_type('float8');},
+);
+
+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");
+
+# check that parameter logging can be disabled
+$log_contents = query_log(
+ { "auto_explain.log_parameter_max_length" => 0 },
+ q{PREPARE get_type(name) AS SELECT * FROM pg_type WHERE typname = $1; EXECUTE get_type('float8');},
+);
+
+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");
+
+# emit some json too
+$log_contents = query_log({ "auto_explain.log_format" => "json" },
+ "SELECT * FROM pg_proc;");
+
+like(
+ $log_contents,
+ 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,
"sequential scan logged, json mode");
+$log_contents = query_log(
+ { "auto_explain.log_format" => "json" },
+ q{PREPARE get_class(name) AS SELECT * FROM pg_class WHERE relname = $1; EXECUTE get_class('pg_class');},
+);
+
+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/"Query Parameters": "\$1 = 'pg_class'"/,
+ "query parameters logged, json mode");
+
like(
$log_contents,
qr/"Node Type": "Index Scan"[^}]*"Index Name": "pg_class_relname_nsp_index"/s,
"index scan logged, json mode");
+$node->stop('fast');
+
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
* Re: Logging query parmeters in auto_explain
2022-05-31 20:33 Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-07 07:53 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-07 11:18 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-09 01:44 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-09 22:55 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
@ 2022-06-14 07:50 ` Michael Paquier <michael@paquier.xyz>
2022-06-27 11:22 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
0 siblings, 1 reply; 15+ messages in thread
From: Michael Paquier @ 2022-06-14 07:50 UTC (permalink / raw)
To: Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>; +Cc: pgsql-hackers@lists.postgresql.org
On Thu, Jun 09, 2022 at 11:55:11PM +0100, Dagfinn Ilmari Mannsåker wrote:
> Done (and more tests added), v3 attached.
One thing I am wondering is if we'd better mention errdetail_params()
at the top of the initial check done in ExplainQueryParameters().
That's a minor issue, though.
+sub query_log
+{
Perhaps a short description at the top of this routine to explain it
is worth it? The test still does a set of like() and unlike() after
running each query when the parameter updates are done. One thing I
would have played with is to group the set of logs expected or not
expected as parameters of the centralized routine, but that would
reduce the customization of the test names, so at the end the approach
you have taken for query_log() looks good to me.
+$node->stop('fast');
There is no need for that. The END block of Cluster.pm does that
already.
--
Michael
Attachments:
signature.asc (application/pgp-signature, 832B) download
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: Logging query parmeters in auto_explain
2022-05-31 20:33 Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-07 07:53 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-07 11:18 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-09 01:44 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-09 22:55 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-14 07:50 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
@ 2022-06-27 11:22 ` Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-27 11:27 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
0 siblings, 1 reply; 15+ messages in thread
From: Dagfinn Ilmari Mannsåker @ 2022-06-27 11:22 UTC (permalink / raw)
To: Michael Paquier <michael@paquier.xyz>; +Cc: pgsql-hackers@lists.postgresql.org
Michael Paquier <michael@paquier.xyz> writes:
> On Thu, Jun 09, 2022 at 11:55:11PM +0100, Dagfinn Ilmari Mannsåker wrote:
>> Done (and more tests added), v3 attached.
>
> One thing I am wondering is if we'd better mention errdetail_params()
> at the top of the initial check done in ExplainQueryParameters().
> That's a minor issue, though.
>
> +sub query_log
> +{
> Perhaps a short description at the top of this routine to explain it
> is worth it?
Done. I also moved the function to the bottom of the file, to avoid
distracting from the actual test queries.
> The test still does a set of like() and unlike() after running each
> query when the parameter updates are done. One thing I would have
> played with is to group the set of logs expected or not expected as
> parameters of the centralized routine, but that would reduce the
> customization of the test names, so at the end the approach you have
> taken for query_log() looks good to me.
I did consider passing the tests as a data structure to the function,
but that would amount to specifying exactly the same things but as a
data structure, and then calling the appropriate function by reference,
which just makes things more cluttered.
If we were using TAP subtests, it might make a sense to have the
function run each set of related tests in a subtest, rather than having
multiple subtest calls at the top level, but we don't, so it doesn't.
> +$node->stop('fast');
> There is no need for that. The END block of Cluster.pm does that
> already.
Ah, I was not aware of that. The call was there in the original version,
so I had just left it in. Removed.
v4 patch attached.
- ilmari
Attachments:
v4-0001-Log-query-parameters-in-auto_explain.patch (text/x-diff, 9.5K) download
From 1c504beecdf2a0e64a7bbd1d0e07b6b33fdc533b 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 v4] 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 tho reset the GUCs after each test.
---
contrib/auto_explain/auto_explain.c | 15 +++
contrib/auto_explain/t/001_auto_explain.pl | 134 ++++++++++++++++++---
doc/src/sgml/auto-explain.sgml | 19 +++
src/backend/commands/explain.c | 22 ++++
src/include/commands/explain.h | 1 +
5 files changed, 177 insertions(+), 14 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..2d04147090 100644
--- a/contrib/auto_explain/t/001_auto_explain.pl
+++ b/contrib/auto_explain/t/001_auto_explain.pl
@@ -17,41 +17,147 @@
$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';");
+my $log_contents = query_log("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';");
+like(
+ $log_contents,
+ qr/Query Text: SELECT \* FROM pg_class;/,
+ "query text logged, text mode");
-$node->stop('fast');
-
-my $log = $node->logfile();
-
-my $log_contents = slurp_file($log);
+unlike(
+ $log_contents,
+ qr/Query Parameters:/,
+ "no query parameters logged when none, text mode");
like(
$log_contents,
qr/Seq Scan on pg_class/,
"sequential scan logged, text mode");
+# with parameters
+$log_contents = query_log(
+ 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/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");
+# check that logged parameters can be truncated
+$log_contents = query_log(
+ 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");
+
+# check that parameter logging can be disabled
+$log_contents = query_log(
+ 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");
+
+# emit some json too
+$log_contents = query_log("SELECT * FROM pg_proc;",
+ { "auto_explain.log_format" => "json" });
+
+like(
+ $log_contents,
+ 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,
"sequential scan logged, json mode");
+# and with parameters
+$log_contents = query_log(
+ 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/"Query Parameters": "\$1 = 'pg_class'"/,
+ "query parameters logged, json mode");
+
like(
$log_contents,
qr/"Node Type": "Index Scan"[^}]*"Index Name": "pg_class_relname_nsp_index"/s,
"index scan logged, json mode");
done_testing();
+
+# 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 ($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;
+}
+
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
* Re: Logging query parmeters in auto_explain
2022-05-31 20:33 Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-07 07:53 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-07 11:18 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-09 01:44 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-09 22:55 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-14 07:50 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-27 11:22 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
@ 2022-06-27 11:27 ` Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-28 07:54 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
0 siblings, 1 reply; 15+ messages in thread
From: Dagfinn Ilmari Mannsåker @ 2022-06-27 11:27 UTC (permalink / raw)
To: Michael Paquier <michael@paquier.xyz>; +Cc: pgsql-hackers@lists.postgresql.org
Dagfinn Ilmari Mannsåker <ilmari@ilmari.org> writes:
> Michael Paquier <michael@paquier.xyz> writes:
>
>> On Thu, Jun 09, 2022 at 11:55:11PM +0100, Dagfinn Ilmari Mannsåker wrote:
>>> Done (and more tests added), v3 attached.
>>
>> One thing I am wondering is if we'd better mention errdetail_params()
>> at the top of the initial check done in ExplainQueryParameters().
>> That's a minor issue, though.
>>
>> +sub query_log
>> +{
>> Perhaps a short description at the top of this routine to explain it
>> is worth it?
>
> Done. I also moved the function to the bottom of the file, to avoid
> distracting from the actual test queries.
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.
- ilmari
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: Logging query parmeters in auto_explain
2022-05-31 20:33 Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-07 07:53 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-07 11:18 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-09 01:44 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-09 22:55 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-14 07:50 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-27 11:22 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-27 11:27 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
@ 2022-06-28 07:54 ` Michael Paquier <michael@paquier.xyz>
2022-06-28 09:12 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
0 siblings, 1 reply; 15+ messages in thread
From: Michael Paquier @ 2022-06-28 07:54 UTC (permalink / raw)
To: Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>; +Cc: pgsql-hackers@lists.postgresql.org
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
Attachments: download all (3 files, .tar.gz)
v5-0001-Refactor-TAP-test-of-auto_explain.patch (text/x-diff, 3.7K) download
From 17899218c72b43794832bb55c0e785bbdf3e97ea Mon Sep 17 00:00:00 2001
From: Michael Paquier <michael@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
v5-0002-Log-query-parameters-in-auto_explain.patch (text/x-diff, 7.3K) download
From 2d9e496f8ccd9a1b14c785609f27dd94c4cfd5a9 Mon Sep 17 00:00:00 2001
From: Michael Paquier <michael@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
* Re: Logging query parmeters in auto_explain
2022-05-31 20:33 Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-07 07:53 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-07 11:18 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-09 01:44 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-09 22:55 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-14 07:50 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-27 11:22 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-27 11:27 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-28 07:54 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
@ 2022-06-28 09:12 ` Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-29 00:17 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
0 siblings, 1 reply; 15+ messages in thread
From: Dagfinn Ilmari Mannsåker @ 2022-06-28 09:12 UTC (permalink / raw)
To: Michael Paquier <michael@paquier.xyz>; +Cc: pgsql-hackers@lists.postgresql.org
Michael Paquier <michael@paquier.xyz> writes:
> 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.
That makes sense, but I still think the query_log() function definition
should go at the end (after done_testing()), so the machinery doesn't
distract from what's actually being tested.
Also, the second paragraph of the second commit message now belongs in
the first commit (without the word "Also").
Thanks,
ilmari
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: Logging query parmeters in auto_explain
2022-05-31 20:33 Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-07 07:53 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-07 11:18 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-09 01:44 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-09 22:55 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-14 07:50 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-27 11:22 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-27 11:27 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-28 07:54 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-28 09:12 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
@ 2022-06-29 00:17 ` Michael Paquier <michael@paquier.xyz>
2022-07-01 00:58 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
0 siblings, 1 reply; 15+ messages in thread
From: Michael Paquier @ 2022-06-29 00:17 UTC (permalink / raw)
To: Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>; +Cc: pgsql-hackers@lists.postgresql.org
On Tue, Jun 28, 2022 at 10:12:18AM +0100, Dagfinn Ilmari Mannsåker wrote:
> That makes sense, but I still think the query_log() function definition
> should go at the end (after done_testing()), so the machinery doesn't
> distract from what's actually being tested.
The majority of TAP scripts have their subroutines at the beginning of
the script, and there are few having that at the end. I won't fight
you on that, but the former is more consistent.
> Also, the second paragraph of the second commit message now belongs in
> the first commit (without the word "Also").
Yep, will fix. I usually rewrite commit messages before merging them.
--
Michael
Attachments:
signature.asc (application/pgp-signature, 832B) download
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: Logging query parmeters in auto_explain
2022-05-31 20:33 Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-07 07:53 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-07 11:18 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-09 01:44 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-09 22:55 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-14 07:50 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-27 11:22 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-27 11:27 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-28 07:54 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-28 09:12 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-29 00:17 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
@ 2022-07-01 00:58 ` Michael Paquier <michael@paquier.xyz>
2022-07-06 01:02 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
0 siblings, 1 reply; 15+ messages in thread
From: Michael Paquier @ 2022-07-01 00:58 UTC (permalink / raw)
To: Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>; +Cc: pgsql-hackers@lists.postgresql.org
On Wed, Jun 29, 2022 at 09:17:49AM +0900, Michael Paquier wrote:
> The majority of TAP scripts have their subroutines at the beginning of
> the script, and there are few having that at the end. I won't fight
> you on that, but the former is more consistent.
I have kept things as I originally intended, and applied 0001 for the
refactoring pieces.
--
Michael
Attachments:
signature.asc (application/pgp-signature, 832B) download
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: Logging query parmeters in auto_explain
2022-05-31 20:33 Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-07 07:53 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-07 11:18 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-09 01:44 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-09 22:55 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-14 07:50 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-27 11:22 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-27 11:27 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-28 07:54 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-28 09:12 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-29 00:17 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-07-01 00:58 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
@ 2022-07-06 01:02 ` Michael Paquier <michael@paquier.xyz>
2022-07-06 09:57 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
0 siblings, 1 reply; 15+ messages in thread
From: Michael Paquier @ 2022-07-06 01:02 UTC (permalink / raw)
To: Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>; +Cc: pgsql-hackers@lists.postgresql.org
On Fri, Jul 01, 2022 at 09:58:52AM +0900, Michael Paquier wrote:
> I have kept things as I originally intended, and applied 0001 for the
> refactoring pieces.
And done as well with 0002. So we are good for this thread.
--
Michael
Attachments:
signature.asc (application/pgp-signature, 832B) download
^ permalink raw reply [nested|flat] 15+ messages in thread
* Re: Logging query parmeters in auto_explain
2022-05-31 20:33 Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-07 07:53 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-07 11:18 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-09 01:44 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-09 22:55 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-14 07:50 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-27 11:22 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-27 11:27 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-28 07:54 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-06-28 09:12 ` Re: Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-29 00:17 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-07-01 00:58 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
2022-07-06 01:02 ` Re: Logging query parmeters in auto_explain Michael Paquier <michael@paquier.xyz>
@ 2022-07-06 09:57 ` Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
0 siblings, 0 replies; 15+ messages in thread
From: Dagfinn Ilmari Mannsåker @ 2022-07-06 09:57 UTC (permalink / raw)
To: Michael Paquier <michael@paquier.xyz>; +Cc: pgsql-hackers@lists.postgresql.org
On Wed, 6 Jul 2022, at 02:02, Michael Paquier wrote:
> On Fri, Jul 01, 2022 at 09:58:52AM +0900, Michael Paquier wrote:
>> I have kept things as I originally intended, and applied 0001 for the
>> refactoring pieces.
>
> And done as well with 0002. So we are good for this thread.
Thanks!
- ilmari
^ permalink raw reply [nested|flat] 15+ messages in thread
end of thread, other threads:[~2022-07-06 09:57 UTC | newest]
Thread overview: 15+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2022-05-31 20:33 Logging query parmeters in auto_explain Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-06 17:12 ` Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-07 07:53 ` Michael Paquier <michael@paquier.xyz>
2022-06-07 11:18 ` Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-09 01:44 ` Michael Paquier <michael@paquier.xyz>
2022-06-09 22:55 ` Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-14 07:50 ` Michael Paquier <michael@paquier.xyz>
2022-06-27 11:22 ` Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-27 11:27 ` Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-28 07:54 ` Michael Paquier <michael@paquier.xyz>
2022-06-28 09:12 ` Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
2022-06-29 00:17 ` Michael Paquier <michael@paquier.xyz>
2022-07-01 00:58 ` Michael Paquier <michael@paquier.xyz>
2022-07-06 01:02 ` Michael Paquier <michael@paquier.xyz>
2022-07-06 09:57 ` Dagfinn Ilmari Mannsåker <ilmari@ilmari.org>
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