Thread: Re: Auto-explain patch

Ooops. That last patch had an embarrassing little typo which caused it to not
actually record the planner times.

This new version fixes that and also includes a little patch to psql so that it
ignores any backend notices during tab-completion, which otherwise just get
in the way. Trace during tab-completion still goes to the server log, if enabled,
since this might actually be useful for debugging psql.

> * trace_min_planner_duration - int, PGC_USERSET
> * trace_min_executor_duration - int, PGC_USERSET
> * trace_explain_plan - bool, PGC_USERSET
>

I'm toying with the idea of adding another parameter, just for convenience:

* auto_trace = on | off

If trace_min_planner_duration and trace_min_executor_duration are both -1,
then setting auto_trace=on would be equivalent to setting
trace_min_planner_duration=0, trace_min_executor_duration=0 and
trace_explain_plan=on, causing *all* statements to be timed and explained
(similar to Oracle's AUTOTRACE).

If either of trace_min_planner_duration or trace_min_executor_duration
are> -1, then auto_trace will do nothing, and only those queries that are
slow to plan and/or execute would be logged.

I'll hold off actually do any more with this for now though, because I feel
that there are still a couple of questions not fully answered:

* Is a whole new logging level (TRACE) overkill for this, or would it
potentially have other uses in the future? My feeling is that it works quite
nicely.

* It it safe to open this up to ordinary users, or do more restrictions need
to be put on it, and if so what?

Regards, Dean

_________________________________________________________________
The John Lewis Clearance - save up to 50% with FREE delivery
http://clk.atdmt.com/UKM/go/101719806/direct/01/

On Fri, 2008-07-11 at 09:33 +0000, Dean Rasheed wrote:

> This new version

Thanks, I'll review this next week now.

-- Simon Riggs           www.2ndQuadrant.comPostgreSQL Training, Services and Support

Dean Rasheed <dean_rasheed@hotmail.com> writes:
> This new version fixes that and also includes a little patch to psql so that it
> ignores any backend notices during tab-completion, which otherwise just get
> in the way. Trace during tab-completion still goes to the server log, if enabled,
> since this might actually be useful for debugging psql.

Comments:

I do not think that you should invent a new elog level for this, and
especially not one that is designed to send unexpected messages to the
client.  Having to kluge tab completion like that is just a signal that
you're going to break a lot of other clients too.  It seems to me that
the right behavior for auto-explain messages is to go only to the log by
default, which means that LOG is already a perfectly good elog level for
auto-explain messages.

Drop the query_string addition to PlannedStmt --- there are other ways
you can get that string in CVS HEAD.  I don't think that planner_time
belongs there either.  It would be impossible to define a principled way
to compare two PlannedStmts for equality with that in there.  Nor do I
see the point of doing it the way you're doing it.  Why don't you just
log the slow planning cycle immediately upon detecting it in planner()?
I don't see that a slow planning cycle has anything necessarily to do
with a slow execution cycle, so IMHO they ought to just get logged
independently.

Please do not export ExplainState --- that's an internal matter for
explain.c.  Export some wrapper function with a cleaner API than
explain_outNode, instead.
        regards, tom lane

Thanks for the feedback, and sorry for my delay in replying (I was on
holiday).

> Tom Lane wrote:
>
> Comments:
>
> I do not think that you should invent a new elog level for this, and
> especially not one that is designed to send unexpected messages to the
> client. Having to kluge tab completion like that is just a signal that
> you're going to break a lot of other clients too. It seems to me that
> the right behavior for auto-explain messages is to go only to the log by
> default, which means that LOG is already a perfectly good elog level for
> auto-explain messages.

The more I thought about this, the more I thought that it was OTT to
add a new elog level just for this, so I agree it should probably just
go to the LOG elog level.

I don't agree with your reasoning on tab-completion though. I actually
think that this is a signal of a broken client. If the user sets
client_min_messages to LOG or lower, and has any of the other logging
or debugging parameters enabled, the output tramples all over the
suggested completions. I don't think the average user is interested in
log/debug output from the queries psql does internally during
tab-completion. So IMHO the tab-completion 'kludge', is still
worthwhile, regardless of the rest of the patch.


> Drop the query_string addition to PlannedStmt --- there are other ways
> you can get that string in CVS HEAD.

OK. What is the best way to get this string now? Are you referring to
debug_query_string, or is there another way?


> I don't think that planner_time
> belongs there either. It would be impossible to define a principled way
> to compare two PlannedStmts for equality with that in there. Nor do I
> see the point of doing it the way you're doing it. Why don't you just
> log the slow planning cycle immediately upon detecting it in planner()?
> I don't see that a slow planning cycle has anything necessarily to do
> with a slow execution cycle, so IMHO they ought to just get logged
> independently.

Makes sense.


> Please do not export ExplainState --- that's an internal matter for
> explain.c. Export some wrapper function with a cleaner API than
> explain_outNode, instead.
>
> regards, tom lane

OK, that's much neater.

I'll try to rework this ASAP but I understand if it's too late for
this commitfest.

Cheers, Dean.

_________________________________________________________________
Win a voice over part with Kung Fu Panda & Live Search   and   100’s of Kung Fu Panda prizes to win with Live Search
http://clk.atdmt.com/UKM/go/107571439/direct/01/

Hi,

I'm very interested in the auto-explain feature.
Are there any plans to re-add it in the next commit-fest?

Dean Rasheed <dean_rasheed@hotmail.com> wrote:

> > Please do not export ExplainState --- that's an internal matter for
> > explain.c. Export some wrapper function with a cleaner API than
> > explain_outNode, instead.
>
> OK, that's much neater.

How about the attached patch?
I exported initialization of ExplainState and explain_outNode call
to a new function ExplainOneResult. It receives executor nodes and
returns the tree as a text.

I think it'd be better to implement the auto-explain feature
not as a core feature but as an extension, because various users
have various desires about the feature. We could write a small extension
moudle using hooks and the ExplainOneResult function. If we includes
the extension as a contrib module, users can mofify it and install
customized version of auto-explain.

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

On Tue, 2008-08-26 at 19:24 +0900, ITAGAKI Takahiro wrote:

> I'm very interested in the auto-explain feature.

Me too, though must apologise I've had no further time to review this.

-- Simon Riggs           www.2ndQuadrant.comPostgreSQL Training, Services and Support

Here is a contrib version of auto-explain.
I'd like to add it the next commit-fest in September.

I set a high value on logging, not on interactive responce because
I think it's enough if we use EXPLAIN ANALYZE directly in psql or
set min_client_messages to LOG.

The module consists of one contrib directory and three patches:

* export_explain.patch
    It exports an internal routine in explain.c as ExplainOneResult().
    Auto-explain module requires it.

* custom_guc_flags.patch
    It enables to use guc flags in custom guc variables.
    Auto-explain module works better with it because there is a millisecond
    unit variable (explain.log_min_duration) in the module.

* psql_ignore_notices.patch
    It suppress notice messages during psql tab-completion and
    \d commands. I extracted it from Dean's patch.
    Auto-explain module does not always need the patch, but I think
    this feature is useful even if we don't use auto-explain.
    psql will ignore annoying messages on non-user SQLs when we set
    min_client_messages to lower level and enable some of log_* or
    debug_* options.

* auto_explain.tgz
    A contrib module version of auto-explain.
    An arguable part is initializing instruments in ExecutorRun_hook.
    The initialization should be done in ExecutorStart normally, but
    it is too late in the hook. Is it safe? or are there any better idea?
    README is a plain-text for now, and I'll rewrite it in sgml if needed.

Comments welcome.


(Here is a copy of README)

auto_explain
------------
Log query plans that execution times are longer than configuration.

Usage
-----
#= LOAD 'auto_explain';
#= SET explain.log_min_duration = 0;
#= SET explain.log_analyze = true;
#= SELECT count(*)
     FROM pg_class, pg_index
    WHERE oid = indrelid AND indisunique;

LOG:  duration: 0.457 ms  plan:
        Aggregate  (cost=14.90..14.91 rows=1 width=0) (actual time=0.444..0.445 rows=1 loops=1)
          ->  Hash Join  (cost=3.91..14.70 rows=81 width=0) (actual time=0.147..0.402 rows=81 loops=1)
                Hash Cond: (pg_class.oid = pg_index.indrelid)
                ->  Seq Scan on pg_class  (cost=0.00..8.27 rows=227 width=4) (actual time=0.011..0.135 rows=227
loops=1)
                ->  Hash  (cost=2.90..2.90 rows=81 width=4) (actual time=0.104..0.104 rows=81 loops=1)
                      ->  Seq Scan on pg_index  (cost=0.00..2.90 rows=81 width=4) (actual time=0.008..0.056 rows=81
loops=1)
                            Filter: indisunique
STATEMENT:  SELECT count(*)
          FROM pg_class, pg_index
         WHERE oid = indrelid AND indisunique;

GUC variables
-------------
* explain.log_min_duration (= -1)
        Sets the minimum execution time above which plans will be logged.
        Zero prints all plans. -1 turns this feature off.

* explain.log_analyze (= false)
        Use EXPLAIN ANALYZE for plan logging.

* explain.log_verbose (= false)
        Use EXPLAIN VERBOSE for plan logging.

You can use shared_preload_libraries or local_preload_libraries to
load the module automatically. If you do so, you also need to add
"explain" in custom_variable_classes and define explain.* variables
in your postgresql.conf.

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

> Here is a contrib version of auto-explain.

OK, I hadn't considered doing it as a module before.

Is it only available to superusers? Do we have a general policy on
this? Most logging options are superuser-only, but the recent changes
to LOG debug_print_* output have left them PGC_USERSET.

Regards, Dean.

_________________________________________________________________
Win a voice over part with Kung Fu Panda & Live Search   and   100’s of Kung Fu Panda prizes to win with Live Search
http://clk.atdmt.com/UKM/go/107571439/direct/01/

Dean Rasheed <dean_rasheed@hotmail.com> wrote:

> Is it only available to superusers?

Presently, yes.

> Do we have a general policy on
> this? Most logging options are superuser-only, but the recent changes
> to LOG debug_print_* output have left them PGC_USERSET.

I set it PGC_SUSET because other log_* options have PGC_SUSET.
I'm not sure what is the difference between log_* and debug_* ...

I think the best policy is to allow general users only to turn "on"
those options, but not to turn "off" if the default setting is on.
We might need to get default values in postgresq.conf in the context
of assignment.

Here is a psesudo code. Is it possible?

bool log_xxx_assign_hook(newval, source)
{   if (by SET command && !superuser())   {       if (default_value == true && newval == false)           elog(ERROR,
"Youcannot turn off the loggging option");   }   return true; /* ok, you can reset it */
 
}

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

> * auto_explain.tgz
> A contrib module version of auto-explain.
> An arguable part is initializing instruments in ExecutorRun_hook.
> The initialization should be done in ExecutorStart normally, but
> it is too late in the hook. Is it safe? or are there any better idea?
> README is a plain-text for now, and I'll rewrite it in sgml if needed.
>

How about adding a new hook to control instrumentation of queries in
ExecutorStart? Something like:

typedef bool (*ExecutorDoInstrument_hook_type) (QueryDesc *queryDesc, int eflags);

extern PGDLLIMPORT ExecutorDoInstrument_hook_type ExecutorDoInstrument_hook;

I think that would allow your module code to be simplified,
and it would allow other future extensions to hook in and
enable instrumentation before queries are run.

Regards, Dean.

_________________________________________________________________
Win a voice over part with Kung Fu Panda & Live Search   and   100’s of Kung Fu Panda prizes to win with Live Search
http://clk.atdmt.com/UKM/go/107571439/direct/01/

Dean Rasheed <dean_rasheed@hotmail.com> wrote:

> > An arguable part is initializing instruments in ExecutorRun_hook.
> > The initialization should be done in ExecutorStart normally, but
> > it is too late in the hook. Is it safe? or are there any better idea?
> 
> How about adding a new hook to control instrumentation of queries in
> ExecutorStart? Something like:
> 
> typedef bool (*ExecutorDoInstrument_hook_type) (QueryDesc *queryDesc, int eflags);
> extern PGDLLIMPORT ExecutorDoInstrument_hook_type ExecutorDoInstrument_hook;

I think it is not good to have any single-purpose hooks -- a new global
variable "bool force_instrument" would be enough for the purpose ;-)

I'd like to suggest on-demand allocation of instruments instead.
PlanState->instrument is not only a runtime statstics collector, but also
represents whether instrumentation is enabled or not. However, we also
have the same information in EState->es_insrument. If we use it instread
of NULL check, we could initialize instrument fields in executor.

[src/backend/executor/execProcnode.c]
ExecProcNode(PlanState *node)
{   ...   if (node->state->es_instrument)   {       if (node->instrument == NULL)           node->instrument =
InstrAlloc(1,long_lived_memory_context);       InstrStartNode(node->instrument);   }
 

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

On 8/28/08, ITAGAKI Takahiro <itagaki.takahiro@oss.ntt.co.jp> wrote:
> Here is a contrib version of auto-explain.

>  You can use shared_preload_libraries or local_preload_libraries to
>  load the module automatically. If you do so, you also need to add
>  "explain" in custom_variable_classes and define explain.* variables
>  in your postgresql.conf.

Is it possible to use LOAD command to load the module?

-- 
marko

"Marko Kreen" <markokr@gmail.com> wrote:

> On 8/28/08, ITAGAKI Takahiro <itagaki.takahiro@oss.ntt.co.jp> wrote:
> >  You can use shared_preload_libraries or local_preload_libraries to
> >  load the module automatically. If you do so, you also need to add
> >  "explain" in custom_variable_classes and define explain.* variables
> >  in your postgresql.conf.
> 
> Is it possible to use LOAD command to load the module?

Yes, but disabled in default.
You need to enable it like:
 LOAD 'auto_explain'; SET explain.log_min_duration = '100ms'; SET explain.log_analyze = true; SELECT ...

In that case, you don't need to define custom_variable_classes.

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

On 9/2/08, ITAGAKI Takahiro <itagaki.takahiro@oss.ntt.co.jp> wrote:
>  "Marko Kreen" <markokr@gmail.com> wrote:
>  > On 8/28/08, ITAGAKI Takahiro <itagaki.takahiro@oss.ntt.co.jp> wrote:
> > >  You can use shared_preload_libraries or local_preload_libraries to
>  > >  load the module automatically. If you do so, you also need to add
>  > >  "explain" in custom_variable_classes and define explain.* variables
>  > >  in your postgresql.conf.
>  >
>  > Is it possible to use LOAD command to load the module?
>
> Yes, but disabled in default.
>  You need to enable it like:
>
>   LOAD 'auto_explain';
>   SET explain.log_min_duration = '100ms';
>
>   SET explain.log_analyze = true;
>
>   SELECT ...
>
>  In that case, you don't need to define custom_variable_classes.

I was interested if it is possible to enable it for single session.
Seems it is.  Good.

-- 
marko

On Wed, Aug 27, 2008 at 8:54 PM, ITAGAKI Takahiro
<itagaki.takahiro@oss.ntt.co.jp> wrote:
> Here is a contrib version of auto-explain.
> I'd like to add it the next commit-fest in September.

Here is my review:

*custom_guc_flags-0828.patch

It seems to be windows newline damaged? lots of ^M at the end of the
lines, could not get it to apply cleanly.  New patch attached.

My only other concern is the changes to DefineCustom*() to tag the new
flags param.  Now I think anyone who uses Custom gucs will want/should
be able to set that. I did not see any people in contrib using it but
did not look on PGfoundry.  Do we need to document the change
somewhere for people who might be using it???

*export_explain.patch:

This looks much better than the old exporting of ExplainState way and
fixes tom's complaint about exporting ExplainState, so looks good to
me.

*psql_ignore_notices-0828.patch:

This is not needed anymore because we log to LOG. (as you pointed out)
Tom also voiced some concern about this possibly breaking (or broken) clients.

I set my client_min_messages to notice and tried tab completing common
things I do.. I did not see any NOTICES, so unless we have an annoying
message someone knows about (and maybe it should not be a notice
then).  I think this should get dropped.

*auto_explalin.c:

init_instrument()

Hrm this strikes me as kind of kludgy...  Any thoughts on the 4 cases
in the switch getting out of sync (T_AppendState, T_BitmapAndState,
T_BitmapOrState, T_SubqueryScanState)?  The only "cleaner" way I can
see is to add a hook for CreateQueryDesc so we can overload
doInstrument and ExecInitNode will InstrAlloc them all for us.
I dunno Suggestions??

use the {outer|inner}PlanState macros instead of ->lefttree, ->righttree

can probably save a few cycles by wrapping those in a
if (outerPlanNode(planstate))

A quick check shows they can be null, but maybe they never can be when
they get to this point... So maybe thats a mute point.

If this sticks around I would suggest restructuring it to better match
explain_outNode so its easier to match up
something like...

if (planstate->initPlan)
    foreach...
        init_instrument()

if (outerPlanState())
    foreach...

if (innerPlanState())

the only other comment I have is suset_assign() do we really need to
be a superuser if its all going to LOG ? There was some concern about
explaining security definer functions right? but surely a regular
explain on those shows the same thing as this explain?  Or what am I
missing?

and obviously your self noted comment that README.txt should be sgml

Thanks for your reviewing, Alex.
I applied your comments to my patch.

- auto_explain.patch : patch against HEAD
- auto_explain.tgz   : contrib module
- autoexplain.sgml   : documentation

"Alex Hunsaker" <badalex@gmail.com> wrote:

> *custom_guc_flags-0828.patch
> My only other concern is the changes to DefineCustom*() to tag the new
> flags param.  Now I think anyone who uses Custom gucs will want/should
> be able to set that. I did not see any people in contrib using it but
> did not look on PGfoundry.  Do we need to document the change
> somewhere for people who might be using it???

Now it is done with DefineCustomVariable(type, variable) and keep
existing functions as-is for backward compatibility.

Some people will be happy if the functions are documented,
but we need to define 'stable-internal-functions' between
SPI (stable expoted functions) and unstable internal functions.


> *psql_ignore_notices-0828.patch:
> I think this should get dropped.

Hmm, I agree that hiding all messages is not good. I removed it.
If some people need it, we can reconsider it in a separated discussion.


> *auto_explalin.c:
> init_instrument()
> The only "cleaner" way I can
> see is to add a hook for CreateQueryDesc so we can overload
> doInstrument and ExecInitNode will InstrAlloc them all for us.

I wanted to avoid modifying core codes as far as possible,
but I see it was ugly. Now I added 'force_instrument' global
variable as a hook for CreateQueryDesc.


> the only other comment I have is suset_assign() do we really need to
> be a superuser if its all going to LOG ? There was some concern about
> explaining security definer functions right? but surely a regular
> explain on those shows the same thing as this explain?  Or what am I
> missing?

Almost logging options in postgres are only for superusers. So I think
auto_explain options should not be modified by non-superusers, too.

If you want to permit usage for users, you can create a security definer
wrapper function to allow it, no?

  CREATE FUNCTION set_explain_log_min_duration(text) RETURNS text AS
    $$ SELECT set_config('explain.log_min_duration', $1, false); $$
  LANGUAGE sql SECURITY DEFINER;

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

On Thu, Oct 9, 2008 at 03:06, ITAGAKI Takahiro
<itagaki.takahiro@oss.ntt.co.jp> wrote:
> Thanks for your reviewing, Alex.
> I applied your comments to my patch.

Sorry for the late reply!  Somehow I missed this, saw it on the commit
fest wiki :)

>> *custom_guc_flags-0828.patch
>> My only other concern is the changes to DefineCustom*() to tag the new
>> flags param.  Now I think anyone who uses Custom gucs will want/should
>> be able to set that. I did not see any people in contrib using it but
>> did not look on PGfoundry.  Do we need to document the change
>> somewhere for people who might be using it???
>
> Now it is done with DefineCustomVariable(type, variable) and keep
> existing functions as-is for backward compatibility.

Ok that seems better...

> Some people will be happy if the functions are documented,
> but we need to define 'stable-internal-functions' between
> SPI (stable expoted functions) and unstable internal functions.

Right, thats why I was asking :)

>> *auto_explalin.c:
>> init_instrument()
>> The only "cleaner" way I can
>> see is to add a hook for CreateQueryDesc so we can overload
>> doInstrument and ExecInitNode will InstrAlloc them all for us.
>
> I wanted to avoid modifying core codes as far as possible,
> but I see it was ugly. Now I added 'force_instrument' global
> variable as a hook for CreateQueryDesc.

Yeah, well if we are not to worried about it getting out of sync when
people add new node/scan types what you had before was probably ok. I
was just trying to stimulate my own and maybe others brains who are on
the list that might have better ideas.  But at least now the commiter
has 2 options here :)

>> the only other comment I have is suset_assign() do we really need to
>> be a superuser if its all going to LOG ? There was some concern about
>> explaining security definer functions right? but surely a regular
>> explain on those shows the same thing as this explain?  Or what am I
>> missing?
>
> Almost logging options in postgres are only for superusers. So I think
> auto_explain options should not be modified by non-superusers, too.

Ok thanks that makes sense.

On Thu, 2008-10-09 at 19:06 +0900, ITAGAKI Takahiro wrote:
> Thanks for your reviewing, Alex.
> I applied your comments to my patch.
>

I made a few changes:

1. fixed some minor issues with auto_explain.sgml so that it would build
(and renamed to auto-explain.sgml to match other files)

2. added link in contrib.sgml

3. added line to contrib/Makefile to build the module

4. bundled it all up as one patch to make it easier to move around

It still needs to be merged with HEAD.

Regards,
    Jeff Davis

On Thu, 2008-10-09 at 19:06 +0900, ITAGAKI Takahiro wrote:
> Thanks for your reviewing, Alex.
> I applied your comments to my patch.

Hi,

This seems like a very useful feature, and it works nicely.

Initial comments:

1. Please sync with HEAD. There was a change made on Oct. 31st that
affects this patch, and prevents it from building properly.

2. Add it to the list of contrib modules to build in contrib/Makefile

Regards,Jeff Davis

Jeff Davis wrote:
> It still needs to be merged with HEAD.
>
ExecutorRun function signature has changed to return void. Other than that
it seems OK. I'll add a few additional notes:

One thing that I noticed was that tab completion queries are also explained
if "explain.log_min_duration" is set to zero. Actually this also applies to
psql \dX commands. Don't know if this is deliberate or not. Example:

load 'auto_explain';
set explain.log_min_duration = 0;
set client_min_messages = LOG;
select * from pg_catalog.^ILOG:  duration: 4.713 ms  plan:
Limit  (cost=27.41..27.44 rows=3 width=85) (actual time=4.023..4.418 rows=75 loops=1)
...

I have a feeling that this can become somewhat annoying during an interactive
troubleshooting session.

Another thing is a feature I am interested in -- ability to auto-explain statements
execututed from within functions. I'm thinking of adding an extra boolean GUC --
"explain.log_nested_statements" (defaults to false). Quick test seems to give
expected results, but there maybe something I missed.

regards,
Martin

*** a/contrib/auto_explain/auto_explain.c
--- b/contrib/auto_explain/auto_explain.c
***************
*** 15,20 **** PG_MODULE_MAGIC;
--- 15,21 ----
  static int        explain_log_min_duration = -1;    /* msec or -1 */
  static bool        explain_log_analyze = false;
  static bool        explain_log_verbose = false;
+ static bool        explain_log_nested = false;

  static bool        toplevel = true;
  static ExecutorRun_hook_type    prev_ExecutorRun = NULL;
***************
*** 28,33 **** static void explain_ExecutorRun(QueryDesc *queryDesc,
--- 29,35 ----
  static bool assign_log_min_duration(int newval, bool doit, GucSource source);
  static bool assign_log_analyze(bool newval, bool doit, GucSource source);
  static bool assign_log_verbose(bool newval, bool doit, GucSource source);
+ static bool assign_log_nested(bool newval, bool doit, GucSource source);

  static struct config_int def_log_min_duration =
  {
***************
*** 67,78 **** static struct config_bool def_log_verbose =
--- 69,93 ----
      false, assign_log_verbose, NULL
  };

+ static struct config_bool def_log_nested_statements =
+ {
+     {
+         GUCNAME("log_nested_statements"),
+         PGC_USERSET,
+         STATS_MONITORING,
+         "Log nested statements."
+     },
+     &explain_log_nested,
+     false, assign_log_nested, NULL
+ };
+
  void
  _PG_init(void)
  {
      DefineCustomVariable(PGC_INT, &def_log_min_duration);
      DefineCustomVariable(PGC_BOOL, &def_log_analyze);
      DefineCustomVariable(PGC_BOOL, &def_log_verbose);
+     DefineCustomVariable(PGC_BOOL, &def_log_nested_statements);

      /* install ExecutorRun_hook */
      prev_ExecutorRun = ExecutorRun_hook;
***************
*** 89,95 **** _PG_fini(void)
  void
  explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, long count)
  {
!     if (toplevel && explain_log_min_duration >= 0)
      {
          instr_time        starttime;
          instr_time        duration;
--- 104,110 ----
  void
  explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, long count)
  {
!     if ((toplevel || explain_log_nested) && explain_log_min_duration >= 0)
      {
          instr_time        starttime;
          instr_time        duration;
***************
*** 188,190 **** assign_log_verbose(bool newval, bool doit, GucSource source)
--- 203,211 ----
  {
      return suset_assign(source, GUCNAME("log_verbose"));
  }
+
+ static bool
+ assign_log_nested(bool newval, bool doit, GucSource source)
+ {
+     return suset_assign(source, GUCNAME("log_nested_statements"));
+ }

On Fri, 2008-11-07 at 18:03 +0200, Martin Pihlak wrote:
> One thing that I noticed was that tab completion queries are also explained
> if "explain.log_min_duration" is set to zero. Actually this also applies to
> psql \dX commands. Don't know if this is deliberate or not. Example:

It's logged at the LOG level, just like log_min_duration_statement, and
seems to have the same behavior. What do you think it should do
differently?

> Another thing is a feature I am interested in -- ability to auto-explain statements
> execututed from within functions. I'm thinking of adding an extra boolean GUC --
> "explain.log_nested_statements" (defaults to false). Quick test seems to give
> expected results, but there maybe something I missed.
> 

I like that idea, I'll take a look at it.

Regards,Jeff Davis

Jeff Davis wrote:
> It's logged at the LOG level, just like log_min_duration_statement, and
> seems to have the same behavior. What do you think it should do
> differently?
> 
There was actually a patch to disable the psql notices, but there were
some concerns and I think it was removed:
http://archives.postgresql.org/pgsql-hackers/2008-07/msg01264.php
http://archives.postgresql.org/pgsql-hackers/2008-09/msg01752.php

Patch is at:
http://archives.postgresql.org/pgsql-hackers/2008-08/msg01274.php
and seems to get rid of the annoying messages. If there aren't any
major issues with it, I think it should be re-added.

regards,
Martin

On Fri, 2008-11-07 at 22:23 +0200, Martin Pihlak wrote:
> Patch is at:
> http://archives.postgresql.org/pgsql-hackers/2008-08/msg01274.php
> and seems to get rid of the annoying messages. If there aren't any
> major issues with it, I think it should be re-added.
> 

I still don't understand why this psql patch is desirable. Who sets
their client_min_messages to LOG in psql? And if they do, why would they
expect different behavior that they always got from the already-existing
GUC log_min_duration_statement?

Regards,Jeff Davis

Martin Pihlak <martin.pihlak@gmail.com> writes:
> There was actually a patch to disable the psql notices, but there were
> some concerns and I think it was removed:
> http://archives.postgresql.org/pgsql-hackers/2008-07/msg01264.php
> http://archives.postgresql.org/pgsql-hackers/2008-09/msg01752.php

> Patch is at:
> http://archives.postgresql.org/pgsql-hackers/2008-08/msg01274.php
> and seems to get rid of the annoying messages. If there aren't any
> major issues with it, I think it should be re-added.

As I said in the first-quoted message, that patch was simply a band-aid
trying to cover poorly designed behavior; and it still is.  The fact is
that most clients will not react very gracefully to unexpected notice
messages, especially not large numbers of same.
        regards, tom lane

Jeff Davis wrote:
> I still don't understand why this psql patch is desirable. Who sets
> their client_min_messages to LOG in psql? And if they do, why would they
> expect different behavior that they always got from the already-existing
> GUC log_min_duration_statement?
> 
I know a few ;) In my environment the auto-explain is especially useful when
used from within psql. Server logs are not always easy to get to, and it is
difficult to extract the interesting bits (large files and lots of log traffic).

For me the primary use of auto-explain would be interactive troubleshooting.
The troublesome statements usually involve several nested function calls and
are tedious to trace manually. With auto-explain I fire up psql, load the
module, set the client log level, run the statements and immediately see
what's going on. I bet that lot of the developers and QA folk would use it
similarly.

You are of course right about the log_min_duration_statement, also the
log_executor_stats etc. behave similarly. So indeed, the "ignore notices" patch
is not necessarily part of auto-explain.

Regards,
Martin

On Sat, 2008-11-08 at 12:18 +0200, Martin Pihlak wrote:
> For me the primary use of auto-explain would be interactive troubleshooting.
> The troublesome statements usually involve several nested function calls and
> are tedious to trace manually. With auto-explain I fire up psql, load the
> module, set the client log level, run the statements and immediately see
> what's going on. I bet that lot of the developers and QA folk would use it
> similarly.
> 

I think the cost in terms of inconsistency here is just too high for the
benefit. If you set the client_min_messages to LOG, you should really
get *all* the log messages, not all except for those that happen to
occur when psql is in some implicit mode that's invisible to the user.

By the way, a possible solution for the problem you describe is to
simply set explain.log_min_duration=1s or something, so that you won't
see tab completion queries (or, if you do, this is the least of your
problems). Or, just disable tab completion.

> You are of course right about the log_min_duration_statement, also the
> log_executor_stats etc. behave similarly. So indeed, the "ignore notices" patch
> is not necessarily part of auto-explain.
> 

I agree that there might be room for improvement in psql's handling of
notices, and that the logging system might be made more flexible. But
let's just keep it simple so that we get something in 8.4. I think
auto-explain will be very useful to a lot of people as-is.

Regards,Jeff Davis

On Fri, 2008-11-07 at 18:03 +0200, Martin Pihlak wrote:
> Another thing is a feature I am interested in -- ability to auto-explain statements
> execututed from within functions. I'm thinking of adding an extra boolean GUC --
> "explain.log_nested_statements" (defaults to false). Quick test seems to give
> expected results, but there maybe something I missed.

Thanks.

I applied this patch for log_nested_statements and I merged with HEAD.
Current patch attached.

One thing I'm unsure of (this question is for ITAGAKI Takahiro): why is
it necessary to define a new function DefineCustomVariable(), when there
are already functions DefineCustomBoolVariable() and
DefineCustomIntVariable()?

Regards,
    Jeff Davis

On Sat, 2008-11-08 at 11:32 -0800, Jeff Davis wrote:
> One thing I'm unsure of (this question is for ITAGAKI Takahiro): why is
> it necessary to define a new function DefineCustomVariable(), when there
> are already functions DefineCustomBoolVariable() and
> DefineCustomIntVariable()?
> 

Oh, I see. It's needed to set the flags to GUC_UNIT_MS.

Another question: what is explain.log_analyze supposed to do? Changing
it doesn't seem to have an effect; it always prints out the actual time.

Regards,Jeff Davis

Thank you for reviewing.

Jeff Davis <pgsql@j-davis.com> wrote:
> Another question: what is explain.log_analyze supposed to do? Changing
> it doesn't seem to have an effect; it always prints out the actual time.

That's because explain.log_analyze requires executor instruments,
and it's not free. I think we'd better to have an option to avoid
the overheads... Oops, I found my bug when force_instrument is
turned on. It should be enabled only when
(explain_log_min_duration >= 0 && explain_log_analyze).

I send a new patch to fix it. A documentation about
explain.log_nested_statements is also added to the sgml file.

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

On Mon, 2008-11-10 at 18:02 +0900, ITAGAKI Takahiro wrote:
> That's because explain.log_analyze requires executor instruments,
> and it's not free. I think we'd better to have an option to avoid
> the overheads... Oops, I found my bug when force_instrument is
> turned on. It should be enabled only when
> (explain_log_min_duration >= 0 && explain_log_analyze).
>
> I send a new patch to fix it. A documentation about
> explain.log_nested_statements is also added to the sgml file.
>

Great. I attached a patch with some minor documentation changes.

There seems to be no auto_explain view, so I assumed that section of the
docs was old, and I removed it. Let me know if you intend to include the
view.

Thanks! This patch is ready to go, as far as I'm concerned.

Regards,
    Jeff Davis

Jeff Davis <pgsql@j-davis.com> writes:
> Thanks! This patch is ready to go, as far as I'm concerned.

This patch seems to contain a subset of the "contrib infrastructure"
patch that's listed separately on the commitfest page.  While I have
no strong objection to what's here, I'm wondering what sort of process
we want to follow.  Is the infrastructure stuff getting separately
reviewed or not?
        regards, tom lane

On Thu, 2008-11-13 at 14:31 -0500, Tom Lane wrote:
> Jeff Davis <pgsql@j-davis.com> writes:
> > Thanks! This patch is ready to go, as far as I'm concerned.
> 
> This patch seems to contain a subset of the "contrib infrastructure"
> patch that's listed separately on the commitfest page.  While I have
> no strong objection to what's here, I'm wondering what sort of process
> we want to follow.  Is the infrastructure stuff getting separately
> reviewed or not?
> 

I can review it, but not until this weekend. It looks like someone
already added me to the list of reviewers on that patch. I'm not sure if
Matthew Wetmore has already started reviewing it or not.

Regards,Jeff Davis

Jeff Davis <pgsql@j-davis.com> writes:
> On Thu, 2008-11-13 at 14:31 -0500, Tom Lane wrote:
>> This patch seems to contain a subset of the "contrib infrastructure"
>> patch that's listed separately on the commitfest page.  While I have
>> no strong objection to what's here, I'm wondering what sort of process
>> we want to follow.  Is the infrastructure stuff getting separately
>> reviewed or not?

> I can review it, but not until this weekend. It looks like someone
> already added me to the list of reviewers on that patch. I'm not sure if
> Matthew Wetmore has already started reviewing it or not.

Now that I look closer, the "contrib infrastructure" item is just a
combination of the auto_explain and pg_stat_statements items, and I
guess the reason you and Matthew were shown as reviewers was that
you'd each been assigned one of those two items.  As far as I can see
this is just confusing and duplicative.  I've removed the
"infrastructure" item from the commitfest page; I think we can
proceed with the two other items separately.  If there's any conflict
in the two patches we can resolve it after the first one gets applied.
        regards, tom lane

Tom Lane <tgl@sss.pgh.pa.us> wrote:

> Now that I look closer, the "contrib infrastructure" item is just a
> combination of the auto_explain and pg_stat_statements items, and I
> guess the reason you and Matthew were shown as reviewers was that
> you'd each been assigned one of those two items.  As far as I can see
> this is just confusing and duplicative.

That's right. Sorry for your confusing.

> I think we can
> proceed with the two other items separately.  If there's any conflict
> in the two patches we can resolve it after the first one gets applied.

contrib/auto_explain patch is "Ready for committer" even without
the QueryDesc patch. So please apply it if there are no problems.
I'll rewrite contrib/pg_stat_statements to use the new feature
in the QueryDesc patch and avoid confliction from the first one.

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

Jeff Davis <pgsql@j-davis.com> writes:
> On Mon, 2008-11-10 at 18:02 +0900, ITAGAKI Takahiro wrote:
>> That's because explain.log_analyze requires executor instruments,
>> and it's not free. I think we'd better to have an option to avoid
>> the overheads... Oops, I found my bug when force_instrument is
>> turned on. It should be enabled only when
>> (explain_log_min_duration >= 0 && explain_log_analyze).
>> 
>> I send a new patch to fix it. A documentation about
>> explain.log_nested_statements is also added to the sgml file.

> Great. I attached a patch with some minor documentation changes.

Looking at this patch now ...

I don't like the force_instrument thing too much at all.  It's brute
force and it doesn't get every case right today, much less in the future
--- for instance, it uselessly forces instrumentation on an EXPLAIN
startup, because it can't react to EXEC_FLAG_EXPLAIN_ONLY.

I think a cleaner solution here is to create a hook for ExecutorStart
just as we have done for ExecutorRun --- and probably there ought to
be one for ExecutorEnd for completeness.  auto_explain would then
hook into ExecutorStart and force doInstrument true on appropriate
conditions.

Another issue that is bothering me is that it's not clear that an
ExecutorRun execution is the right unit for measuring the runtime of a
query --- this would be quite misleading for queries that are executed a
bit at a time, such as SQL functions and cursor queries.  I think it'd
be better to accumulate runtime and then report in an ExecutorEnd hook.
This would likely require adding a struct Instrumentation * field to
QueryDesc in which to track the total ExecutorRun timing, but I don't
see anything very wrong with that.  The core system would just leave it
NULL, and the ExecutorStart hook could fill it in when it wants the
query to be tracked by the other two hooks.
        regards, tom lane

Ok, I'm looking at the direction of ExecutorStart/End hooks...

Tom Lane <tgl@sss.pgh.pa.us> wrote:

> This would likely require adding a struct Instrumentation * field to
> QueryDesc in which to track the total ExecutorRun timing

I think instr_time is enough here,
but why do you think Instrumentation is needed?

There might be another approach to have a stopwatch stack in
the contrib module instead of the core. I think it is cleaner
because it works even if multiple modules use the stopwatch
at the same time. Am I missing something?

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

I wrote:

> There might be another approach to have a stopwatch stack in
> the contrib module instead of the core. I think it is cleaner
> because it works even if multiple modules use the stopwatch
> at the same time. Am I missing something?

Ooops, it should be:
... because each multiple module can use its own stopwatch
stack at the same time.

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

ITAGAKI Takahiro <itagaki.takahiro@oss.ntt.co.jp> writes:
> Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> This would likely require adding a struct Instrumentation * field to
>> QueryDesc in which to track the total ExecutorRun timing

> I think instr_time is enough here,
> but why do you think Instrumentation is needed?

Well, it's more general.  You could think of ExecutorRun as being like a
plan node, in which case all the fields of struct Instrumentation are
potentially useful.  If a contrib module doesn't want to use them,
of course it doesn't have to.

Or I guess we could just put a void * there and not try to wire down
its usage.

> There might be another approach to have a stopwatch stack in
> the contrib module instead of the core. I think it is cleaner
> because it works even if multiple modules use the stopwatch
> at the same time. Am I missing something?

I think this will be mighty messy ...
        regards, tom lane

Here is an update version of contrib/auto_explain patch.

Now it uses new ExecutorStart_hook and ExecutorEnd_hook.
When we execute queries using cursor, FETCHes are accumulated
and reported only once on CLOSE.

A new argument 'flags' is added in DefineCustomXXXVariable()
and custom GUC variables are defined with it. Some GUC_* constants
are moved to guc.h from guc_tables.h.

A variable "Instrumentation *totaltime" is added in QueryDesc.
It is not used by the core in default (always NULL), but initialized
by contrib modules. However, the core update the counter if it is
not NULL because multiple contrib modules might use it.
If the core don't update the counter, only one of the modules
should update it, but it's hard to determine which one should do.


Tom Lane <tgl@sss.pgh.pa.us> wrote:

> >> This would likely require adding a struct Instrumentation * field to
> Well, it's more general.  You could think of ExecutorRun as being like a
> plan node, in which case all the fields of struct Instrumentation are
> potentially useful.  If a contrib module doesn't want to use them,
> of course it doesn't have to.

Instrumentation is enough for auto_explain, so I used it for now.
However, pg_stat_statements also use the field and requires other
counters (buffer usages and rusage). It might replace the field
with another struct. Then we might need to reconsider how to deal
with session statistics, suggested by Vladimir.

"Vladimir Sitnikov" <sitnikov.vladimir@gmail.com> wrote:
> I wish PostgreSQL had some kind of pg_session_statistics view that reports
> resource usage statistics for each session.
> For instance, it could expose "buffer usage" to the client, so it could get
> more details on resource usage. For instance, I would like to see a new tab
> in pgAdmin that shows "total number of buffer gets", "number of WAL records
> created", "number of rows sorted" and similar information after query
> finishes (even in plain "execute" mode).

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

ITAGAKI Takahiro <itagaki.takahiro@oss.ntt.co.jp> writes:
> Here is an update version of contrib/auto_explain patch.

Applied with some editorialization, mostly around the GUC stuff.
        regards, tom lane