Allow auto_explain to log to NOTICE
Hi all
This patch allows a user to configure auto_explain to log to NOTICE instead
of the server log. This allows automated testing of application-generated
queries to ensure correct plans etc from code that can inspect returned
notices but not the server log.
I don't see any tests for auto_explain so haven't added any test cases.
Happy to do so if that's deemed necessary.
Diff is against master. Also at
https://github.com/tomdcc/postgres/tree/auto-explain-notice
Cheers
Tom
Attachments:
auto-explain-notice-v1.diffapplication/octet-stream; name=auto-explain-notice-v1.diffDownload
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
new file mode 100644
index ea4f957..2f5a8f7
*** a/contrib/auto_explain/auto_explain.c
--- b/contrib/auto_explain/auto_explain.c
*************** static bool auto_explain_log_buffers = f
*** 28,33 ****
--- 28,34 ----
static bool auto_explain_log_triggers = false;
static bool auto_explain_log_timing = true;
static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
+ static int auto_explain_log_destination = LOG;
static bool auto_explain_log_nested_statements = false;
static double auto_explain_sample_rate = 1;
*************** static const struct config_enum_entry fo
*** 39,44 ****
--- 40,51 ----
{NULL, 0, false}
};
+ static const struct config_enum_entry destination_options[] = {
+ {"log", LOG, false},
+ {"notice", NOTICE, false},
+ {NULL, 0, false}
+ };
+
/* Current nesting depth of ExecutorRun calls */
static int nesting_level = 0;
*************** _PG_init(void)
*** 141,146 ****
--- 148,165 ----
NULL,
NULL);
+ DefineCustomEnumVariable("auto_explain.log_destination",
+ "Log destination for the plan.",
+ NULL,
+ &auto_explain_log_destination,
+ LOG,
+ destination_options,
+ PGC_SUSET,
+ 0,
+ NULL,
+ NULL,
+ NULL);
+
DefineCustomBoolVariable("auto_explain.log_nested_statements",
"Log nested statements.",
NULL,
*************** explain_ExecutorEnd(QueryDesc *queryDesc
*** 353,359 ****
* reported. This isn't ideal but trying to do it here would
* often result in duplication.
*/
! ereport(LOG,
(errmsg("duration: %.3f ms plan:\n%s",
msec, es->str->data),
errhidestmt(true)));
--- 372,378 ----
* reported. This isn't ideal but trying to do it here would
* often result in duplication.
*/
! ereport(auto_explain_log_destination,
(errmsg("duration: %.3f ms plan:\n%s",
msec, es->str->data),
errhidestmt(true)));
diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml
new file mode 100644
index 08b67f2..bc1b4d7
*** a/doc/src/sgml/auto-explain.sgml
--- b/doc/src/sgml/auto-explain.sgml
*************** LOAD 'auto_explain';
*** 189,194 ****
--- 189,213 ----
<varlistentry>
<term>
+ <varname>auto_explain.log_destination</varname> (<type>enum</type>)
+ <indexterm>
+ <primary><varname>auto_explain.log_destination</> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ <varname>auto_explain.log_destination</varname> selects where
+ auto_explain will log the query plan.
+ The allowed values are <literal>log</literal>, which logs the plan to the
+ server log, and <literal>notice</literal>, which logs it as a NOTICE, which
+ allows clients to access it. <literal>log</literal> is the default.
+ Only superusers can change this setting.
+ </para>
+ </listitem>
+ </varlistentry>
+
+ <varlistentry>
+ <term>
<varname>auto_explain.log_nested_statements</varname> (<type>boolean</type>)
<indexterm>
<primary><varname>auto_explain.log_nested_statements</varname> configuration parameter</primary>
Hi,
On 2018-04-27 11:43:58 +0930, Tom Dunstan wrote:
This patch allows a user to configure auto_explain to log to NOTICE instead
of the server log. This allows automated testing of application-generated
queries to ensure correct plans etc from code that can inspect returned
notices but not the server log.
I don't see any tests for auto_explain so haven't added any test cases.
Happy to do so if that's deemed necessary.
I'd be in favor of adding them.
+static int auto_explain_log_destination = LOG;
I very much dislike this name - it's too similar too the log_destination
GUC, while being about something different. How about "log_level"?
+static const struct config_enum_entry destination_options[] = { + {"log", LOG, false}, + {"notice", NOTICE, false}, + {NULL, 0, false} +};
I'd argue this should contain the non-error cases. It's just as
reasonable to want to add this as a debug level or such.
Greetings,
Andres Freund
(Resent with subscribed email address, thanks gmail)
Hi Andres, thanks for the extremely fast review!
On 27 April 2018 at 11:46, Andres Freund <andres@anarazel.de> wrote:
I don't see any tests for auto_explain so haven't added any test cases.
Happy to do so if that's deemed necessary.
I'd be in favor of adding them.
OK, sure.
+static int auto_explain_log_destination = LOG;
I very much dislike this name - it's too similar too the log_destination
GUC, while being about something different. How about "log_level"?
Works for me.
+static const struct config_enum_entry destination_options[] = {
+ {"log", LOG, false},
+ {"notice", NOTICE, false},
+ {NULL, 0, false}
+};
I'd argue this should contain the non-error cases. It's just as
reasonable to want to add this as a debug level or such.
So all of warning, info, debug and debug1-5?
Thanks
Tom
Import Notes
Reply to msg id not found: CAPPfruwWE_1ty3wntO1LqVXS-DV3+Cwpe-dJyR0w742XaohfA@mail.gmail.com
On 2018-04-27 11:52:18 +0930, Tom Dunstan wrote:
I'd argue this should contain the non-error cases. It's just as
reasonable to want to add this as a debug level or such.So all of warning, info, debug and debug1-5?
Yea. Likely nobody will ever use debug5, but I don't see a point making
that judgement call here.
Greetings,
Andres Freund
Import Notes
Reply to msg id not found: CAPPfruwWE_1ty3wntO1LqVXS-DV3+Cwpe-dJyR0w742XaohfA@mail.gmail.com
"Tom" == Tom Dunstan <pgsql@tomd.cc> writes:
Tom> Hi all
Tom> This patch allows a user to configure auto_explain to log to
Tom> NOTICE instead of the server log. This allows automated testing of
Tom> application-generated queries to ensure correct plans etc from
Tom> code that can inspect returned notices but not the server log.
You do know that you can do
SET client_min_messages = log;
to get all log messages generated within your session sent to the client
as well, yes?
--
Andrew (irc:RhodiumToad)
On 27 Apr 2018, at 04:24, Andres Freund <andres@anarazel.de> wrote:
On 2018-04-27 11:52:18 +0930, Tom Dunstan wrote:
I'd argue this should contain the non-error cases. It's just as
reasonable to want to add this as a debug level or such.So all of warning, info, debug and debug1-5?
Yea. Likely nobody will ever use debug5, but I don't see a point making
that judgement call here.
Did you have a chance to hack up a new version of the patch with Andres’ review
comments? I’m marking this patch as Waiting on Author for now based on the
feedback so far in this thread.
cheers ./daniel
On Wed, Jun 20, 2018 at 2:06 PM, Daniel Gustafsson <daniel@yesql.se> wrote:
On 27 Apr 2018, at 04:24, Andres Freund <andres@anarazel.de> wrote:
On 2018-04-27 11:52:18 +0930, Tom Dunstan wrote:
I'd argue this should contain the non-error cases. It's just as
reasonable to want to add this as a debug level or such.So all of warning, info, debug and debug1-5?
Yea. Likely nobody will ever use debug5, but I don't see a point making
that judgement call here.Did you have a chance to hack up a new version of the patch with Andres’ review
comments? I’m marking this patch as Waiting on Author for now based on the
feedback so far in this thread.
Here is an updated version of the patch. Setting this to "needs review".
I haven't added tests for auto_explain - I think that would be useful
but it's a separate project.
cheers
andrew
--
Andrew Dunstan https://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Attachments:
auto-explain-log-level-v2.patchapplication/octet-stream; name=auto-explain-log-level-v2.patchDownload
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index ea4f957cfa..a6996f15a7 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -28,6 +28,7 @@ static bool auto_explain_log_buffers = false;
static bool auto_explain_log_triggers = false;
static bool auto_explain_log_timing = true;
static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
+static int auto_explain_log_level = LOG;
static bool auto_explain_log_nested_statements = false;
static double auto_explain_sample_rate = 1;
@@ -39,6 +40,20 @@ static const struct config_enum_entry format_options[] = {
{NULL, 0, false}
};
+static const struct config_enum_entry loglevel_options[] = {
+ {"debug", DEBUG2, true},
+ {"debug5", DEBUG5, false},
+ {"debug4", DEBUG4, false},
+ {"debug3", DEBUG3, false},
+ {"debug2", DEBUG2, false},
+ {"debug1", DEBUG1, false},
+ {"info", INFO, false},
+ {"notice", NOTICE, false},
+ {"warning", WARNING, false},
+ {"log", LOG, false},
+ {NULL, 0, false}
+};
+
/* Current nesting depth of ExecutorRun calls */
static int nesting_level = 0;
@@ -141,6 +156,18 @@ _PG_init(void)
NULL,
NULL);
+ DefineCustomEnumVariable("auto_explain.log_level",
+ "Log level for the plan.",
+ NULL,
+ &auto_explain_log_level,
+ LOG,
+ loglevel_options,
+ PGC_SUSET,
+ 0,
+ NULL,
+ NULL,
+ NULL);
+
DefineCustomBoolVariable("auto_explain.log_nested_statements",
"Log nested statements.",
NULL,
@@ -353,7 +380,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
* reported. This isn't ideal but trying to do it here would
* often result in duplication.
*/
- ereport(LOG,
+ ereport(auto_explain_log_level,
(errmsg("duration: %.3f ms plan:\n%s",
msec, es->str->data),
errhidestmt(true)));
diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml
index 08b67f2600..2b928d0806 100644
--- a/doc/src/sgml/auto-explain.sgml
+++ b/doc/src/sgml/auto-explain.sgml
@@ -187,6 +187,27 @@ LOAD 'auto_explain';
</listitem>
</varlistentry>
+ <varlistentry>
+ <term>
+ <varname>auto_explain.log_level</varname> (<type>enum</type>)
+ <indexterm>
+ <primary><varname>auto_explain.log_level</> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ <varname>auto_explain.log_level</varname> selects the log level at which
+ auto_explain will log the query plan.
+ Valid values are <literal>DEBUG5</literal>, <literal>DEBUG4</literal>,
+ <literal>DEBUG3</literal>, <literal>DEBUG2</literal>,
+ <literal>DEBUG1</literal>, <literal>INFO</literal>,
+ <literal>NOTICE</literal>, <literal>WARNING</literal>,
+ and <literal>LOG</literal>. The default is <literal>LOG</literal>.
+ Only superusers can change this setting.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry>
<term>
<varname>auto_explain.log_nested_statements</varname> (<type>boolean</type>)
On 4 Jul 2018, at 15:34, Andrew Dunstan <andrew.dunstan@2ndquadrant.com> wrote:
On Wed, Jun 20, 2018 at 2:06 PM, Daniel Gustafsson <daniel@yesql.se> wrote:
On 27 Apr 2018, at 04:24, Andres Freund <andres@anarazel.de> wrote:
On 2018-04-27 11:52:18 +0930, Tom Dunstan wrote:
I'd argue this should contain the non-error cases. It's just as
reasonable to want to add this as a debug level or such.So all of warning, info, debug and debug1-5?
Yea. Likely nobody will ever use debug5, but I don't see a point making
that judgement call here.Did you have a chance to hack up a new version of the patch with Andres’ review
comments? I’m marking this patch as Waiting on Author for now based on the
feedback so far in this thread.Here is an updated version of the patch. Setting this to "needs review”.
Thanks! Looking at the code, and documentation this seems a worthwhile
addition. Manual testing proves that it works as expected, and the patch
follows the expected style. A few small comments:
Since DEBUG is not a defined loglevel, it seems superfluous to include it here.
It’s also omitted from the documentation so it should probably be omitted from
here.
+ {"debug", DEBUG2, true},
The <varname> tag should be closed with a matching </varname>.
+ <primary><varname>auto_explain.log_level</> configuration parameter</primary>
With those fixed it’s ready for committer.
I haven't added tests for auto_explain - I think that would be useful
but it's a separate project.
Agreeing that this would be beneficial, the attached patch (to apply on top of
the patch in question) takes a stab at adding tests for this new functionality.
In order to test plan output we need to support COSTS in the explain output, so
a new GUC auto_explain.log_costs is added. We also need to not print the
duration, so as a hack this patch omits the duration if auto_explain.log_timing
is set to off and auto_explain.log_analyze is set off. This is a hack and not
a nice overloading, but it seems overkill to add a separate GUC just to turn
off the duration, any better ideas on how support omitting the duration?
cheers ./daniel
Attachments:
auto_explain_tests.diffapplication/octet-stream; name=auto_explain_tests.diff; x-unix-mode=0644Download
diff --git a/contrib/auto_explain/Makefile b/contrib/auto_explain/Makefile
index fcf36c5ab0..db61901830 100644
--- a/contrib/auto_explain/Makefile
+++ b/contrib/auto_explain/Makefile
@@ -4,6 +4,8 @@ MODULE_big = auto_explain
OBJS = auto_explain.o $(WIN32RES)
PGFILEDESC = "auto_explain - logging facility for execution plans"
+REGRESS = auto_explain
+
ifdef USE_PGXS
PG_CONFIG = pg_config
PGXS := $(shell $(PG_CONFIG) --pgxs)
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index ea4f957cfa..5723e4383a 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -27,6 +27,7 @@ static bool auto_explain_log_verbose = false;
static bool auto_explain_log_buffers = false;
static bool auto_explain_log_triggers = false;
static bool auto_explain_log_timing = true;
+static bool auto_explain_log_costs = true;
static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
static bool auto_explain_log_nested_statements = false;
static double auto_explain_sample_rate = 1;
@@ -129,6 +130,17 @@ _PG_init(void)
NULL,
NULL);
+ DefineCustomBoolVariable("auto_explain.log_costs",
+ "Include costs in plans.",
+ NULL,
+ &auto_explain_log_costs,
+ true,
+ PGC_SUSET,
+ 0,
+ NULL,
+ NULL,
+ NULL);
+
DefineCustomEnumVariable("auto_explain.log_format",
"EXPLAIN format to be used for plan logging.",
NULL,
@@ -309,6 +321,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
if (queryDesc->totaltime && auto_explain_enabled() && current_query_sampled)
{
double msec;
+ StringInfoData buf;
/*
* Make sure stats accumulation is done. (Note: it's okay if several
@@ -328,6 +341,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
es->timing = (es->analyze && auto_explain_log_timing);
es->summary = es->analyze;
es->format = auto_explain_log_format;
+ es->costs = auto_explain_log_costs;
ExplainBeginOutput(es);
ExplainQueryText(es, queryDesc);
@@ -347,18 +361,24 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
es->str->data[es->str->len - 1] = '}';
}
+ initStringInfo(&buf);
+
+ if (es->analyze || auto_explain_log_timing)
+ appendStringInfo(&buf, "duration: %.3f ms ", msec);
+
/*
* Note: we rely on the existing logging of context or
* debug_query_string to identify just which statement is being
* reported. This isn't ideal but trying to do it here would
* often result in duplication.
*/
ereport(auto_explain_log_level,
- (errmsg("duration: %.3f ms plan:\n%s",
- msec, es->str->data),
+ (errmsg("%splan:\n%s",
+ buf.data, es->str->data),
errhidestmt(true)));
pfree(es->str->data);
+ pfree(buf.data);
}
}
diff --git a/contrib/auto_explain/expected/auto_explain.out b/contrib/auto_explain/expected/auto_explain.out
new file mode 100644
index 0000000000..070d28b667
--- /dev/null
+++ b/contrib/auto_explain/expected/auto_explain.out
@@ -0,0 +1,67 @@
+LOAD 'auto_explain';
+SET auto_explain.log_min_duration = 0;
+SET auto_explain.log_level = NOTICE;
+SET auto_explain.log_timing = off;
+SET auto_explain.log_costs = off;
+-- Should log
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+NOTICE: plan:
+Query Text: SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+Index Only Scan using pg_class_relname_nsp_index on pg_class
+ Index Cond: (relname = 'pg_class'::name)
+ ?column?
+----------
+
+(1 row)
+
+SET auto_explain.log_verbose = on;
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+NOTICE: plan:
+Query Text: SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+Index Only Scan using pg_class_relname_nsp_index on pg_catalog.pg_class
+ Output: NULL::text
+ Index Cond: (pg_class.relname = 'pg_class'::name)
+ ?column?
+----------
+
+(1 row)
+
+SET auto_explain.log_format = json;
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+NOTICE: plan:
+{
+ "Query Text": "SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';",
+ "Plan": {
+ "Node Type": "Index Only Scan",
+ "Parallel Aware": false,
+ "Scan Direction": "Forward",
+ "Index Name": "pg_class_relname_nsp_index",
+ "Relation Name": "pg_class",
+ "Schema": "pg_catalog",
+ "Alias": "pg_class",
+ "Output": ["NULL::text"],
+ "Index Cond": "(pg_class.relname = 'pg_class'::name)"
+ }
+}
+ ?column?
+----------
+
+(1 row)
+
+-- Shouldn't log due to too high loglevel
+SET auto_explain.log_level = DEBUG5;
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+ ?column?
+----------
+
+(1 row)
+
+-- Shouldn't log due to query being too fast
+SET auto_explain.log_level = NOTICE;
+SET auto_explain.log_min_duration = 1000;
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+ ?column?
+----------
+
+(1 row)
+
diff --git a/contrib/auto_explain/sql/auto_explain.sql b/contrib/auto_explain/sql/auto_explain.sql
new file mode 100644
index 0000000000..8f7b05274e
--- /dev/null
+++ b/contrib/auto_explain/sql/auto_explain.sql
@@ -0,0 +1,25 @@
+LOAD 'auto_explain';
+
+SET auto_explain.log_min_duration = 0;
+SET auto_explain.log_level = NOTICE;
+SET auto_explain.log_timing = off;
+SET auto_explain.log_costs = off;
+
+-- Should log
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+
+SET auto_explain.log_verbose = on;
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+
+SET auto_explain.log_format = json;
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+
+-- Shouldn't log due to too high loglevel
+SET auto_explain.log_level = DEBUG5;
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+
+-- Shouldn't log due to query being too fast
+SET auto_explain.log_level = NOTICE;
+SET auto_explain.log_min_duration = 1000;
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+
diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml
index 08b67f2600..25f445e1bb 100644
--- a/doc/src/sgml/auto-explain.sgml
+++ b/doc/src/sgml/auto-explain.sgml
@@ -108,6 +108,24 @@ LOAD 'auto_explain';
</listitem>
</varlistentry>
+ <varlistentry>
+ <term>
+ <varname>auto_explain.log_costs</varname> (<type>boolean</type>)
+ <indexterm>
+ <primary><varname>auto_explain.log_costs</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ <varname>auto_explain.log_costs</varname> controls whether per node costs
+ are printed when an execution plan is logged; it's
+ equivalent to the <literal>COSTS</literal> option of <command>EXPLAIN</command>.
+ This parameter is on by default.
+ Only superusers can change this setting.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry>
<term>
<varname>auto_explain.log_timing</varname> (<type>boolean</type>)
@@ -124,8 +142,8 @@ LOAD 'auto_explain';
queries significantly on some systems, so it may be useful to set this
parameter to off when only actual row counts, and not exact times, are
needed.
- This parameter has no effect
- unless <varname>auto_explain.log_analyze</varname> is enabled.
+ This parameter has turns on printing the duration of the plan if
+ <varname>auto_explain.log_analyze</varname> is disabled.
This parameter is on by default.
Only superusers can change this setting.
</para>
On 07/17/2018 12:04 PM, Daniel Gustafsson wrote:
On 4 Jul 2018, at 15:34, Andrew Dunstan <andrew.dunstan@2ndquadrant.com> wrote:
On Wed, Jun 20, 2018 at 2:06 PM, Daniel Gustafsson <daniel@yesql.se> wrote:
On 27 Apr 2018, at 04:24, Andres Freund <andres@anarazel.de> wrote:
On 2018-04-27 11:52:18 +0930, Tom Dunstan wrote:
I'd argue this should contain the non-error cases. It's just as
reasonable to want to add this as a debug level or such.So all of warning, info, debug and debug1-5?
Yea. Likely nobody will ever use debug5, but I don't see a point making
that judgement call here.Did you have a chance to hack up a new version of the patch with Andres’ review
comments? I’m marking this patch as Waiting on Author for now based on the
feedback so far in this thread.Here is an updated version of the patch. Setting this to "needs review”.
Thanks for the review
Thanks! Looking at the code, and documentation this seems a worthwhile
addition. Manual testing proves that it works as expected, and the patch
follows the expected style. A few small comments:Since DEBUG is not a defined loglevel, it seems superfluous to include it here.
It’s also omitted from the documentation so it should probably be omitted from
here.+ {"debug", DEBUG2, true},
I treated this like we do for client_min_messages and log_min_messages -
the alias is there but I don;t think we document it either.
I don't mind removing it, was just trying to be consistent. It seems odd
that we would accept it in one place but not another.
The <varname> tag should be closed with a matching </varname>.
+ <primary><varname>auto_explain.log_level</> configuration parameter</primary>
With those fixed it’s ready for committer.
Thanks, will fix.
I haven't added tests for auto_explain - I think that would be useful
but it's a separate project.Agreeing that this would be beneficial, the attached patch (to apply on top of
the patch in question) takes a stab at adding tests for this new functionality.In order to test plan output we need to support COSTS in the explain output, so
a new GUC auto_explain.log_costs is added. We also need to not print the
duration, so as a hack this patch omits the duration if auto_explain.log_timing
is set to off and auto_explain.log_analyze is set off. This is a hack and not
a nice overloading, but it seems overkill to add a separate GUC just to turn
off the duration, any better ideas on how support omitting the duration?
Great, I'll check it out.
cheers
andrew
--
Andrew Dunstan https://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On 17 Jul 2018, at 19:11, Andrew Dunstan <andrew.dunstan@2ndquadrant.com> wrote:
On 07/17/2018 12:04 PM, Daniel Gustafsson wrote:
Since DEBUG is not a defined loglevel, it seems superfluous to include it here.
It’s also omitted from the documentation so it should probably be omitted from
here.+ {"debug", DEBUG2, true},
I treated this like we do for client_min_messages and log_min_messages - the alias is there but I don;t think we document it either.
I don't mind removing it, was just trying to be consistent. It seems odd that we would accept it in one place but not another.
Ooh.. I didn’t know that alias existed and didn’t find it when poking at the
code. In that case I agree with you, the alias should stay so I withdraw that
comment. I learned something new today =)
I haven't added tests for auto_explain - I think that would be useful
but it's a separate project.Agreeing that this would be beneficial, the attached patch (to apply on top of
the patch in question) takes a stab at adding tests for this new functionality.In order to test plan output we need to support COSTS in the explain output, so
a new GUC auto_explain.log_costs is added. We also need to not print the
duration, so as a hack this patch omits the duration if auto_explain.log_timing
is set to off and auto_explain.log_analyze is set off. This is a hack and not
a nice overloading, but it seems overkill to add a separate GUC just to turn
off the duration, any better ideas on how support omitting the duration?Great, I'll check it out.
I’m not sure it’s worth adding this much to the code just to be able to test
it, but it seemed like a good excercise to write to have something to reason
about.
cheers ./daniel
On 07/17/2018 02:03 PM, Daniel Gustafsson wrote:
On 17 Jul 2018, at 19:11, Andrew Dunstan <andrew.dunstan@2ndquadrant.com> wrote:
On 07/17/2018 12:04 PM, Daniel Gustafsson wrote:
Since DEBUG is not a defined loglevel, it seems superfluous to include it here.
It’s also omitted from the documentation so it should probably be omitted from
here.+ {"debug", DEBUG2, true},
I treated this like we do for client_min_messages and log_min_messages - the alias is there but I don;t think we document it either.
I don't mind removing it, was just trying to be consistent. It seems odd that we would accept it in one place but not another.
Ooh.. I didn’t know that alias existed and didn’t find it when poking at the
code. In that case I agree with you, the alias should stay so I withdraw that
comment. I learned something new today =)
Committed with the doc fix belatedly.
I haven't added tests for auto_explain - I think that would be useful
but it's a separate project.Agreeing that this would be beneficial, the attached patch (to apply on top of
the patch in question) takes a stab at adding tests for this new functionality.In order to test plan output we need to support COSTS in the explain output, so
a new GUC auto_explain.log_costs is added. We also need to not print the
duration, so as a hack this patch omits the duration if auto_explain.log_timing
is set to off and auto_explain.log_analyze is set off. This is a hack and not
a nice overloading, but it seems overkill to add a separate GUC just to turn
off the duration, any better ideas on how support omitting the duration?Great, I'll check it out.
I’m not sure it’s worth adding this much to the code just to be able to test
it, but it seemed like a good excercise to write to have something to reason
about.
I think it probably is, buit I'm not very happy about the hack, so I
didn't commit it. Please submit this to the next commitfest, possibly
with a nicer way of managing the duration logging.
cheers
andrew
--
Andrew Dunstan https://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On 31 Jul 2018, at 14:23, Andrew Dunstan <andrew.dunstan@2ndquadrant.com> wrote:
I’m not sure it’s worth adding this much to the code just to be able to test
it, but it seemed like a good excercise to write to have something to reason
about.I think it probably is, buit I'm not very happy about the hack, so I didn't commit it. Please submit this to the next commitfest, possibly with a nicer way of managing the duration logging.
Circling back to this, I updated the patch with providing another option as I
couldn’t think of another way to do it cleanly. I’ll add the patch to the next
CF but as it’s just about to start it should be moved to the next once started.
cheers ./daniel
Attachments:
auto_explain_tests-v2.diffapplication/octet-stream; name=auto_explain_tests-v2.diff; x-unix-mode=0644Download
From 0bb615ec6fa326cf816c54edf0ea6cea4ab91d67 Mon Sep 17 00:00:00 2001
From: Daniel Gustafsson <daniel@yesql.se>
Date: Tue, 30 Oct 2018 11:19:51 +0100
Subject: [PATCH] Add costs and duration options to auto_explain
This adds additional options to auto_explain for controlling logging
of costs and the query duration. While being able to turn costs on or
off can be useful, the main driver is to be able to properly test the
extension. This commit adds basic test coverage to auto_explain using
the options introduced to keep the test output stable.
---
contrib/auto_explain/Makefile | 2 +
contrib/auto_explain/auto_explain.c | 39 +++++++++++++--
contrib/auto_explain/expected/auto_explain.out | 68 ++++++++++++++++++++++++++
contrib/auto_explain/sql/auto_explain.sql | 26 ++++++++++
doc/src/sgml/auto-explain.sgml | 34 +++++++++++++
5 files changed, 165 insertions(+), 4 deletions(-)
create mode 100644 contrib/auto_explain/expected/auto_explain.out
create mode 100644 contrib/auto_explain/sql/auto_explain.sql
diff --git a/contrib/auto_explain/Makefile b/contrib/auto_explain/Makefile
index fcf36c5ab0..db61901830 100644
--- a/contrib/auto_explain/Makefile
+++ b/contrib/auto_explain/Makefile
@@ -4,6 +4,8 @@ MODULE_big = auto_explain
OBJS = auto_explain.o $(WIN32RES)
PGFILEDESC = "auto_explain - logging facility for execution plans"
+REGRESS = auto_explain
+
ifdef USE_PGXS
PG_CONFIG = pg_config
PGXS := $(shell $(PG_CONFIG) --pgxs)
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index 646cd0d42c..89fd317cb2 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -28,6 +28,8 @@ static bool auto_explain_log_verbose = false;
static bool auto_explain_log_buffers = false;
static bool auto_explain_log_triggers = false;
static bool auto_explain_log_timing = true;
+static bool auto_explain_log_costs = true;
+static bool auto_explain_log_duration = true;
static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
static int auto_explain_log_level = LOG;
static bool auto_explain_log_nested_statements = false;
@@ -145,6 +147,29 @@ _PG_init(void)
NULL,
NULL);
+ DefineCustomBoolVariable("auto_explain.log_costs",
+ "Include costs in plans.",
+ NULL,
+ &auto_explain_log_costs,
+ true,
+ PGC_SUSET,
+ 0,
+ NULL,
+ NULL,
+ NULL);
+
+ DefineCustomBoolVariable("auto_explain.log_duration",
+ "Log the duration of the query.",
+ NULL,
+ &auto_explain_log_duration,
+ true,
+ PGC_SUSET,
+ 0,
+ NULL,
+ NULL,
+ NULL);
+
+
DefineCustomEnumVariable("auto_explain.log_format",
"EXPLAIN format to be used for plan logging.",
NULL,
@@ -356,6 +381,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
es->timing = (es->analyze && auto_explain_log_timing);
es->summary = es->analyze;
es->format = auto_explain_log_format;
+ es->costs = auto_explain_log_costs;
ExplainBeginOutput(es);
ExplainQueryText(es, queryDesc);
@@ -383,10 +409,15 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
* reported. This isn't ideal but trying to do it here would
* often result in duplication.
*/
- ereport(auto_explain_log_level,
- (errmsg("duration: %.3f ms plan:\n%s",
- msec, es->str->data),
- errhidestmt(true)));
+ if (auto_explain_log_duration)
+ ereport(auto_explain_log_level,
+ (errmsg("duration: %.3f ms plan:\n%s",
+ msec, es->str->data),
+ errhidestmt(true)));
+ else
+ ereport(auto_explain_log_level,
+ (errmsg("plan:\n%s", es->str->data),
+ errhidestmt(true)));
pfree(es->str->data);
}
diff --git a/contrib/auto_explain/expected/auto_explain.out b/contrib/auto_explain/expected/auto_explain.out
new file mode 100644
index 0000000000..461343b1e1
--- /dev/null
+++ b/contrib/auto_explain/expected/auto_explain.out
@@ -0,0 +1,68 @@
+LOAD 'auto_explain';
+SET auto_explain.log_min_duration = 0;
+SET auto_explain.log_duration = off;
+SET auto_explain.log_level = NOTICE;
+SET auto_explain.log_timing = off;
+SET auto_explain.log_costs = off;
+-- Should log
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+NOTICE: plan:
+Query Text: SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+Index Only Scan using pg_class_relname_nsp_index on pg_class
+ Index Cond: (relname = 'pg_class'::name)
+ ?column?
+----------
+
+(1 row)
+
+SET auto_explain.log_verbose = on;
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+NOTICE: plan:
+Query Text: SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+Index Only Scan using pg_class_relname_nsp_index on pg_catalog.pg_class
+ Output: NULL::text
+ Index Cond: (pg_class.relname = 'pg_class'::name)
+ ?column?
+----------
+
+(1 row)
+
+SET auto_explain.log_format = json;
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+NOTICE: plan:
+{
+ "Query Text": "SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';",
+ "Plan": {
+ "Node Type": "Index Only Scan",
+ "Parallel Aware": false,
+ "Scan Direction": "Forward",
+ "Index Name": "pg_class_relname_nsp_index",
+ "Relation Name": "pg_class",
+ "Schema": "pg_catalog",
+ "Alias": "pg_class",
+ "Output": ["NULL::text"],
+ "Index Cond": "(pg_class.relname = 'pg_class'::name)"
+ }
+}
+ ?column?
+----------
+
+(1 row)
+
+-- Shouldn't log due to too high loglevel
+SET auto_explain.log_level = DEBUG5;
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+ ?column?
+----------
+
+(1 row)
+
+-- Shouldn't log due to query being too fast
+SET auto_explain.log_level = NOTICE;
+SET auto_explain.log_min_duration = 1000;
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+ ?column?
+----------
+
+(1 row)
+
diff --git a/contrib/auto_explain/sql/auto_explain.sql b/contrib/auto_explain/sql/auto_explain.sql
new file mode 100644
index 0000000000..cea1be3ec1
--- /dev/null
+++ b/contrib/auto_explain/sql/auto_explain.sql
@@ -0,0 +1,26 @@
+LOAD 'auto_explain';
+
+SET auto_explain.log_min_duration = 0;
+SET auto_explain.log_duration = off;
+SET auto_explain.log_level = NOTICE;
+SET auto_explain.log_timing = off;
+SET auto_explain.log_costs = off;
+
+-- Should log
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+
+SET auto_explain.log_verbose = on;
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+
+SET auto_explain.log_format = json;
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+
+-- Shouldn't log due to too high loglevel
+SET auto_explain.log_level = DEBUG5;
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+
+-- Shouldn't log due to query being too fast
+SET auto_explain.log_level = NOTICE;
+SET auto_explain.log_min_duration = 1000;
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
+
diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml
index 120b168d45..be06a29139 100644
--- a/doc/src/sgml/auto-explain.sgml
+++ b/doc/src/sgml/auto-explain.sgml
@@ -108,6 +108,40 @@ LOAD 'auto_explain';
</listitem>
</varlistentry>
+ <varlistentry>
+ <term>
+ <varname>auto_explain.log_costs</varname> (<type>boolean</type>)
+ <indexterm>
+ <primary><varname>auto_explain.log_costs</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ <varname>auto_explain.log_costs</varname> controls whether per node costs
+ are printed when an execution plan is logged; it's
+ equivalent to the <literal>COSTS</literal> option of <command>EXPLAIN</command>.
+ This parameter is on by default.
+ Only superusers can change this setting.
+ </para>
+ </listitem>
+ </varlistentry>
+
+ <varlistentry>
+ <term>
+ <varname>auto_explain.log_duration</varname> (<type>boolean</type>)
+ <indexterm>
+ <primary><varname>auto_explain.log_duration</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ <varname>auto_explain.log_duration</varname> controls whether the logged
+ plan is prefixed with the duration of the query. This parameter is on by
+ default. Only superusers can change this setting.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry>
<term>
<varname>auto_explain.log_timing</varname> (<type>boolean</type>)
--
2.14.1.145.gb3622a4ee
On Tue, Oct 30, 2018 at 11:44:42AM +0100, Daniel Gustafsson wrote:
Circling back to this, I updated the patch with providing another
option as I couldn’t think of another way to do it cleanly. I’ll
add the patch to the next CF but as it’s just about to start it
should be moved to the next once started.
+-- Shouldn't log due to query being too fast
+SET auto_explain.log_level = NOTICE;
+SET auto_explain.log_min_duration = 1000;
+SELECT NULL FROM pg_catalog.pg_class WHERE relname = 'pg_class';
I am ready to be that 1s is not enough as some buildfarm machines are
legendary slow. Honestly, to not have more to worry about I think
that this bit should be dropped."auto_explain.log_duration" should actually be named log_summary,
except that it defaults to true to be backward-compatible, while for
EXPLAIN the default is false, no? It would be nice to be consistent
with EXPLAIN for those options for the naming at least. The default
behavior of those parameters would be inconsistent as the duration is
showed by default with auto_explain and not with EXPLAIN, but it does
not seem like a good idea to change that..
--
Michael
On 26/12/2018 06:42, Michael Paquier wrote:
On Tue, Oct 30, 2018 at 11:44:42AM +0100, Daniel Gustafsson wrote:
Circling back to this, I updated the patch with providing another
option as I couldn’t think of another way to do it cleanly. I’ll
add the patch to the next CF but as it’s just about to start it
should be moved to the next once started.
Do we really want to add user-facing options just to be able to run
tests? Should we write the tests differently instead?
--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On Fri, Jan 04, 2019 at 01:06:24PM +0100, Peter Eisentraut wrote:
Do we really want to add user-facing options just to be able to run
tests? Should we write the tests differently instead?
The take is that the output of the plans generated includes data which
is run-dependent because the duration of the plan is generated
unconditionally. One way to write generic tests considering this
would be to use a TAP test, but I feel that's overdoing it just for
this case.
Being able to control if the plan duration shows up still looks like
an interesting option to me independently of adding tests.
--
Michael
(Michael: sorry for not having responded to your comments on the patch, $life
has had little time over for hacking lately)
On 4 Jan 2019, at 13:49, Michael Paquier <michael@paquier.xyz> wrote:
On Fri, Jan 04, 2019 at 01:06:24PM +0100, Peter Eisentraut wrote:
Do we really want to add user-facing options just to be able to run
tests? Should we write the tests differently instead?
I voiced this concern upthread as well, not being sure if it’s worth the added
complexity.
The take is that the output of the plans generated includes data which
is run-dependent because the duration of the plan is generated
unconditionally. One way to write generic tests considering this
would be to use a TAP test, but I feel that's overdoing it just for
this case.Being able to control if the plan duration shows up still looks like
an interesting option to me independently of adding tests.
There is that. We might not be excited about writing tests for this contrib
module but someone else might want to use this for testing their application in
a similar manner to how pg_regress tests?
cheers ./daniel
On Fri, Jan 04, 2019 at 02:45:55PM +0100, Daniel Gustafsson wrote:
(Michael: sorry for not having responded to your comments on the patch, $life
has had little time over for hacking lately)
No worries, I understand.
There is that. We might not be excited about writing tests for this
contrib module but someone else might want to use this for testing
their application in a similar manner to how pg_regress tests?
If we don't introduce it, there is no way to know. Still if somebody
needs to create regression tests they could just use EXPLAIN for the
same purpose. However, the option still seems useful to me to get out
plans with the most generic output, so I support the idea. If others
don't feel so, I am fine to give up as well.
--
Michael
On 5 Jan 2019, at 01:04, Michael Paquier <michael@paquier.xyz> wrote:
On Fri, Jan 04, 2019 at 02:45:55PM +0100, Daniel Gustafsson wrote:
(Michael: sorry for not having responded to your comments on the patch, $life
has had little time over for hacking lately)No worries, I understand.
There is that. We might not be excited about writing tests for this
contrib module but someone else might want to use this for testing
their application in a similar manner to how pg_regress tests?If we don't introduce it, there is no way to know. Still if somebody
needs to create regression tests they could just use EXPLAIN for the
same purpose. However, the option still seems useful to me to get out
plans with the most generic output, so I support the idea. If others
don't feel so, I am fine to give up as well.
This didn’t attract any other interested parties, and I don’t feel the added
complexity is worth a continued discussion, so I’m closing this patch. Thanks
for the review.
cheers ./daniel