Thread: 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
Attachment
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:
OK, sure.
Works for me.
So all of warning, info, debug and debug1-5?
Thanks
Tom
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
Attachment
> 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
Attachment
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
Attachment
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
Attachment
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
Attachment
(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
Attachment
> 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