Allow auto_explain to log to NOTICE

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

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

"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

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

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

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