Обсуждение: 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

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
documentit 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
documentit 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
notanother.
 
> 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
nextcommitfest, 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