Re: [HACKERS] Auto-explain patch

2008-09-27 Thread Alex Hunsaker 
On Wed, Aug 27, 2008 at 8:54 PM, ITAGAKI Takahiro
[EMAIL PROTECTED] 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


custom_guc_flags.patch
Description: Binary data

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-09-02 Thread Marko Kreen 
On 8/28/08, ITAGAKI Takahiro [EMAIL PROTECTED] 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

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-09-02 Thread ITAGAKI Takahiro 

Marko Kreen [EMAIL PROTECTED] wrote:

 On 8/28/08, ITAGAKI Takahiro [EMAIL PROTECTED] 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



-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-09-02 Thread Marko Kreen 
On 9/2/08, ITAGAKI Takahiro [EMAIL PROTECTED] wrote:
  Marko Kreen [EMAIL PROTECTED] wrote:
   On 8/28/08, ITAGAKI Takahiro [EMAIL PROTECTED] 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

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-09-01 Thread ITAGAKI Takahiro 

Dean Rasheed [EMAIL PROTECTED] 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



-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-08-31 Thread Dean Rasheed 

 * 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/
-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-08-28 Thread Dean Rasheed 

 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/
-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-08-28 Thread ITAGAKI Takahiro 

Dean Rasheed [EMAIL PROTECTED] 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, You cannot turn off the loggging option);
}
return true; /* ok, you can reset it */
}

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



-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-08-27 Thread ITAGAKI Takahiro 
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



custom_guc_flags-0828.patch
Description: Binary data


export_explain.patch
Description: Binary data


psql_ignore_notices-0828.patch
Description: Binary data


auto_explain-0828.tgz
Description: Binary data

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-08-26 Thread ITAGAKI Takahiro 
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 [EMAIL PROTECTED] 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



export_explain.patch
Description: Binary data

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-08-26 Thread Simon Riggs 

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.com
 PostgreSQL Training, Services and Support


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-08-03 Thread Dean Rasheed 

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/
-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-07-26 Thread Tom Lane 
Dean Rasheed [EMAIL PROTECTED] 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

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-07-11 Thread Dean Rasheed 

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/*** ./src/backend/commands/copy.c.orig	2008-07-09 16:14:54.0 +0100
--- ./src/backend/commands/copy.c	2008-07-09 16:15:54.0 +0100
***
*** 1042,1047 
--- 1042,1048 
  
  		/* plan the query */
  		plan = planner(query, 0, NULL);
+ 		plan-query_string = queryString;
  
  		/*
  		 * Use a snapshot with an updated command ID to ensure this query sees
*** ./src/backend/commands/explain.c.orig	2008-07-08 13:55:29.0 +0100
--- ./src/backend/commands/explain.c	2008-07-09 16:14:28.0 +0100
***
*** 40,65 
  explain_get_index_name_hook_type explain_get_index_name_hook = NULL;
  
  
- typedef struct ExplainState
- {
- 	/* options */
- 	bool		printTList;		/* print plan targetlists */
- 	bool		printAnalyze;	/* print actual times */
- 	/* other states */
- 	PlannedStmt *pstmt;			/* top of plan */
- 	List	   *rtable;			/* range table */
- } ExplainState;
- 
  static void ExplainOneQuery(Query *query, ExplainStmt *stmt,
  const char *queryString,
  ParamListInfo params, TupOutputState *tstate);
  static void report_triggers(ResultRelInfo *rInfo, bool show_relname,
  StringInfo buf);
- static double elapsed_time(instr_time *starttime);
- static void explain_outNode(StringInfo str,
- Plan *plan, PlanState *planstate,
- Plan *outer_plan,
- int indent, ExplainState *es);
  static void show_plan_tlist(Plan *plan,
  			StringInfo str, int indent, ExplainState *es);
  static void show_scan_qual(List *qual, const char *qlabel,
--- 40,50 
***
*** 170,175 
--- 155,161 
  
  		/* plan the query */
  		plan = planner(query, 0, params);
+ 		plan-query_string = queryString;
  
  		/* run it (if needed) and produce output */
  		ExplainOnePlan(plan, params, stmt, tstate);
***
*** 384,390 
  }
  
  /* Compute elapsed time in seconds since given timestamp */
! static double
  elapsed_time(instr_time *starttime)
  {
  	instr_time	endtime;
--- 370,376 
  }
  
  /* Compute elapsed time in seconds since given timestamp */
! double
  elapsed_time(instr_time *starttime)
  {
  	instr_time	endtime;
***
*** 406,412 
   * side of a join with the current node.  This is only interesting for
   * deciphering runtime keys of an inner indexscan.
   */
! static void
  explain_outNode(StringInfo str,
  Plan *plan, PlanState *planstate,
  Plan *outer_plan,
--- 392,398 
   * side of a join with the current node.  This is only interesting for
   * deciphering runtime keys of an inner indexscan.
   */
! void
  explain_outNode(StringInfo str,
  Plan *plan, PlanState *planstate,
  Plan *outer_plan,
*** ./src/backend/executor/execMain.c.orig	2008-07-08 14:03:34.0 +0100
--- ./src/backend/executor/execMain.c	2008-07-10 15:17:31.0 +0100
***
*** 39,44 
--- 39,45 
  #include catalog/heap.h
  #include catalog/namespace.h
  #include catalog/toasting.h
+ #include commands/explain.h
  #include commands/tablespace.h
  #include commands/trigger.h
  #include executor/execdebug.h
***
*** 52,57 
--- 53,59 
  #include storage/lmgr.h
  #include storage/smgr.h
  #include utils/acl.h
+ #include utils/guc.h
  #include utils/lsyscache.h

Re: [HACKERS] Auto-explain patch

2008-07-11 Thread Simon Riggs 

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

 This new version

Thanks, I'll review this next week now.

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


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-07-10 Thread Simon Riggs 

On Wed, 2008-07-09 at 09:11 +, Dean Rasheed wrote:
 Simon, I like your proposal, and I think I can see how to code it
 fairly easily.
 
 There is one thing that it doesn't allow, however, which the debug_xxx
 parameters do, and that is for a non-superuser to trace SQL used in
 functions, from an interactive client session. For me, this is quite a
 big thing, because I find it most convienient to turn these parameters
 on while writing and tweaking stored procedures, and have the output
 go straight to my psql window, without having to connect as a superuser
 and trawl through log files.
 
 So I suggest grouping these parameters in their own category
 (eg. sql_trace) and then having additional parameters to control
 where the output would go. So the sql_trace parameters would be:
 
 * sql_trace_min_planner_duration
 * sql_trace_min_executor_duration
 * sql_trace_explain_plan
 
 and they would work exactly as you describe, except they would be
 settable by normal users. Then the destination(s) for the statement
 and EXPLAIN logging would be controlled by:
 
 * client_sql_trace = on | off - settable by a normal user to allow a
 client session to see the sql_trace output. If this parameter is on,
 the sql_trace will be logged as NOTICE output.

After sleeping on this, I think we should follow your idea.

If its possible to do the sql_trace_* parameters as a single one, I
would prefer it, since it makes it more practical to use dynamically.
Not sure how...maybe with a wrapper function?

sql_trace(integer) sets just sql_trace_min_executor_duration
sql_trace(integer, boolean) sets executor and explain
sql_trace(integer, integer, boolean) sets all 3

I think you probably need to drop the sql_ off the front because of
parameter length only.

No need for the other log_... parameter though.

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


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-07-10 Thread Gregory Stark 
Simon Riggs [EMAIL PROTECTED] writes:

 On Wed, 2008-07-09 at 09:11 +, Dean Rasheed wrote:
 
 So I suggest grouping these parameters in their own category
 (eg. sql_trace) and then having additional parameters to control
 where the output would go. So the sql_trace parameters would be:
 
 * sql_trace_min_planner_duration
 * sql_trace_min_executor_duration
 * sql_trace_explain_plan
 
 If its possible to do the sql_trace_* parameters as a single one, I
 would prefer it, since it makes it more practical to use dynamically.
 Not sure how...maybe with a wrapper function?

 sql_trace(integer) sets just sql_trace_min_executor_duration
 sql_trace(integer, boolean) sets executor and explain
 sql_trace(integer, integer, boolean) sets all 3

Fwiw it seems to me trace_sql_* would be nicer, much as we have
track_* guc parameters.

Though I also wonder if there's really any distinction here between tracing
and logging like log_explain_plan and so on. Perhaps we should keep the word
trace for a more in-detail facility.

-- 
  Gregory Stark
  EnterpriseDB  http://www.enterprisedb.com
  Ask me about EnterpriseDB's 24x7 Postgres support!

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-07-10 Thread Dean Rasheed 

 After sleeping on this, I think we should follow your idea.


Hmm. I preferred your idea ;-) It reduces the number of new parameters
back down to 3, which makes it easier to use:

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

(I already decided to drop the sql_) with all output going to new level TRACE
as you described. So output goes to client and not server log by default as
soon as either of the first 2 parameters is enabled.

I've attached what I've done so far, which works according to the above
description. I've not done much testing or written any docs yet, It would be
good to know if this is along the right lines.

Changing parameter names is easy, although admittedly very important to
get right. You didn't say why you changed your mind on this?

I'm more concerned about any possible security holes it opens up.
For SQL in SQL functions, it just gives the function name and statement
number. For EXECUTEd queries, it doesn't have access to the SQL, so
it just logs the other stuff and any context info. For plpgsql functions it will
log values which appear as literals in any queries, but actually
debug_print_parse exposes far more info in this case.

_
100’s of Nikon cameras to be won with Live Search
http://clk.atdmt.com/UKM/go/101719808/direct/01/*** ./src/backend/commands/copy.c.orig	2008-07-09 16:14:54.0 +0100
--- ./src/backend/commands/copy.c	2008-07-09 16:15:54.0 +0100
***
*** 1042,1047 
--- 1042,1048 
  
  		/* plan the query */
  		plan = planner(query, 0, NULL);
+ 		plan-query_string = queryString;
  
  		/*
  		 * Use a snapshot with an updated command ID to ensure this query sees
*** ./src/backend/commands/explain.c.orig	2008-07-08 13:55:29.0 +0100
--- ./src/backend/commands/explain.c	2008-07-09 16:14:28.0 +0100
***
*** 40,65 
  explain_get_index_name_hook_type explain_get_index_name_hook = NULL;
  
  
- typedef struct ExplainState
- {
- 	/* options */
- 	bool		printTList;		/* print plan targetlists */
- 	bool		printAnalyze;	/* print actual times */
- 	/* other states */
- 	PlannedStmt *pstmt;			/* top of plan */
- 	List	   *rtable;			/* range table */
- } ExplainState;
- 
  static void ExplainOneQuery(Query *query, ExplainStmt *stmt,
  const char *queryString,
  ParamListInfo params, TupOutputState *tstate);
  static void report_triggers(ResultRelInfo *rInfo, bool show_relname,
  StringInfo buf);
- static double elapsed_time(instr_time *starttime);
- static void explain_outNode(StringInfo str,
- Plan *plan, PlanState *planstate,
- Plan *outer_plan,
- int indent, ExplainState *es);
  static void show_plan_tlist(Plan *plan,
  			StringInfo str, int indent, ExplainState *es);
  static void show_scan_qual(List *qual, const char *qlabel,
--- 40,50 
***
*** 170,175 
--- 155,161 
  
  		/* plan the query */
  		plan = planner(query, 0, params);
+ 		plan-query_string = queryString;
  
  		/* run it (if needed) and produce output */
  		ExplainOnePlan(plan, params, stmt, tstate);
***
*** 384,390 
  }
  
  /* Compute elapsed time in seconds since given timestamp */
! static double
  elapsed_time(instr_time *starttime)
  {
  	instr_time	endtime;
--- 370,376 
  }
  
  /* Compute elapsed time in seconds since given timestamp */
! double
  elapsed_time(instr_time *starttime)
  {
  	instr_time	endtime;
***
*** 406,412 
   * side of a join with the current node.  This is only interesting for
   * deciphering runtime keys of an inner indexscan.
   */
! static void
  explain_outNode(StringInfo str,
  Plan *plan, PlanState *planstate,
  Plan *outer_plan,
--- 392,398 
   * side of a join with the current node.  This is only interesting for
   * deciphering runtime keys of an inner indexscan.
   */
! void
  explain_outNode(StringInfo str,
  Plan *plan, PlanState *planstate,
  Plan *outer_plan,
*** ./src/backend/executor/execMain.c.orig	2008-07-08 14:03:34.0 +0100
--- ./src/backend/executor/execMain.c	2008-07-10 10:34:26.0 +0100
***
*** 39,44 
--- 39,45 
  #include catalog/heap.h
  #include catalog/namespace.h
  #include catalog/toasting.h
+ #include commands/explain.h
  #include commands/tablespace.h
  #include commands/trigger.h
  #include executor/execdebug.h
***
*** 52,57 
--- 53,59 
  #include storage/lmgr.h
  #include storage/smgr.h
  #include utils/acl.h
+ #include utils/guc.h
  #include utils/lsyscache.h
  #include utils/memutils.h
  #include utils/snapmgr.h
***
*** 184,189 
--- 186,199 
  	}
  
  	/*
+ 	 * If we are tracing and explaining slow-running queries,
+ 	 * enable instrumentation
+ 	 */
+ 	if (trace_explain_plan 
+ 		(trace_min_planner_duration  -1 || trace_min_executor_duration  -1))
+

Re: [HACKERS] Auto-explain patch

2008-07-09 Thread Dean Rasheed 

Simon, I like your proposal, and I think I can see how to code it
fairly easily.

There is one thing that it doesn't allow, however, which the debug_xxx
parameters do, and that is for a non-superuser to trace SQL used in
functions, from an interactive client session. For me, this is quite a
big thing, because I find it most convienient to turn these parameters
on while writing and tweaking stored procedures, and have the output
go straight to my psql window, without having to connect as a superuser
and trawl through log files.

So I suggest grouping these parameters in their own category
(eg. sql_trace) and then having additional parameters to control
where the output would go. So the sql_trace parameters would be:

* sql_trace_min_planner_duration
* sql_trace_min_executor_duration
* sql_trace_explain_plan

and they would work exactly as you describe, except they would be
settable by normal users. Then the destination(s) for the statement
and EXPLAIN logging would be controlled by:

* client_sql_trace = on | off - settable by a normal user to allow a
client session to see the sql_trace output. If this parameter is on,
the sql_trace will be logged as NOTICE output.

* log_sql_trace = on | off - settable only by superusers. If this
parameter is on, the sql_trace will be logged as LOG output, and the
normal client sessions will see nothing (unless they set client_sql_trace).

If both client_sql_trace and log_sql_trace are on, then the output
goes to both locations, and if both are off, then the sql_trace
parameters would do nothing.

Dean


 Subject: RE: [HACKERS] Auto-explain patch
 From: [EMAIL PROTECTED]
 To: [EMAIL PROTECTED]
 CC: pgsql-hackers@postgresql.org
 Date: Mon, 7 Jul 2008 18:03:15 +0100


 On Sun, 2008-07-06 at 17:58 +, Dean Rasheed wrote:

 OK, this one should work against CVS HEAD.

 OK, still getting some offsets, but it applies.

 The patch now outputs things in a useful way to avoid a flood of
 information, that's good.

 The code seems fine, but it doesn't link up with the other logging code
 in postgres.c. That split also seems to drive the way the parameters
 work, so you have another set of parameters mirroring the
 log_min_duration_statement infrastructure. Fairly yuk, but I understand
 why you've done this. It does however beg some serious questions about
 the way we currently do logging.

 The patch as it stands would produce EXPLAIN output for queries that
 will never be logged, which isn't very useful. So Dean, right now I feel
 this version of the patch must be rejected while we discuss how things
 might work differently. Not an issue with the patch, so much as issues
 with the code being patched.

 So thinking about the issues we can either ignore them or tackle them:

 Ignoring problem option: Rewrite this patch as an executor plugin, using
 Itagaki Takahiro's new infrastructure. It's an option, but I guess Dave
 will have something to say about that...

 Fix problems: Having logging in two separate places is ugly and leads to
 the problem of logging EXPLAINs and SQL completely separately, which
 isn't very useful.

 If we put all the logging code in the executor we miss out any parsing
 and planning time but we can log statements and explains for SPI queries
 also.

 We could move the logging of the EXPLAIN to postgres.c, but then we'd
 need to make querydescs live a little longer than desirable, or we
 trigger the EXPLAIN code using some guess at what the planning overhead
 was, a horrible kluge.

 Neither way is clean. So how do we do it?

 My proposal would be to introduce some new logging statements that work
 similarly to, yet as an alternative to log_min_duration_statement.

 * log_min_planner_duration - logs any statement whose planning time
 exceeds the value in ms (-1 is off).
 e.g. LOG planner time: %s ms statement: %s

 * log_min_executor_duration - logs any execution whose execution time
 exceeds the value in ms (-1 is off). We need to pass query text through
 to the executor, depending upon whether its a portal's source text or an
 incoming simple querystring. (This is similar, but not quite the same as
 current patch's debug_explain_min_duration).
 e.g. LOG executor time: %s ms statement: %s

 * log_explain = on | off - logs EXPLAIN if either
 log_min_executor_duration or log_min_planner_duration triggers. We
 output the explain on the same line as the SQL statement, so we don't
 need to play games to link up the output later. (This is similar to, but
 not quite the same as current patch's debug_explain_plan).
 e.g. LOG executor time: %s ms statement: %s

 If both log_min_executor_duration and log_min_planner_duration trigger
 then we get only one log line like this:
 e.g. LOG planner time: %s ms executor time: %s ms statement: %s

 We should call these parameters log_xxx not debug_xxx because we want
 them for production logging.

 If either of these new parameters is -1 then
 log_min_duration_statement does not trigger. (Or we simply make

Re: [HACKERS] Auto-explain patch

2008-07-09 Thread ITAGAKI Takahiro 

Dean Rasheed [EMAIL PROTECTED] wrote:

 * client_sql_trace = on | off - settable by a normal user to allow a
 client session to see the sql_trace output. If this parameter is on,
 the sql_trace will be logged as NOTICE output.

In terms of security, is it ok to show normal users SQLs used in functions
that are owned by other users? Users can call not-owned functions only if
they have EXECUTE privilege on them. -- presently we can see function
bodies from pg_proc.prosrc freely, though.

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



-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-07-09 Thread Simon Riggs 

On Wed, 2008-07-09 at 09:11 +, Dean Rasheed wrote:
 Simon, I like your proposal, and I think I can see how to code it
 fairly easily.
 
 There is one thing that it doesn't allow, however, which the debug_xxx
 parameters do, and that is for a non-superuser to trace SQL used in
 functions, from an interactive client session. For me, this is quite a
 big thing, because I find it most convienient to turn these parameters
 on while writing and tweaking stored procedures, and have the output
 go straight to my psql window, without having to connect as a superuser
 and trawl through log files.

Understood.

 So I suggest grouping these parameters in their own category
 (eg. sql_trace) and then having additional parameters to control
 where the output would go. So the sql_trace parameters would be:
 
 * sql_trace_min_planner_duration
 * sql_trace_min_executor_duration
 * sql_trace_explain_plan
 
 and they would work exactly as you describe, except they would be
 settable by normal users. 

This is already possible, if your crafty.

 Then the destination(s) for the statement
 and EXPLAIN logging would be controlled by:
 
 * client_sql_trace = on | off - settable by a normal user to allow a
 client session to see the sql_trace output. If this parameter is on,
 the sql_trace will be logged as NOTICE output.

Just set client_min_messages = 'LOG';

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


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-07-09 Thread Marko Kreen 
On 7/9/08, ITAGAKI Takahiro [EMAIL PROTECTED] wrote:
  Dean Rasheed [EMAIL PROTECTED] wrote:
  * client_sql_trace = on | off - settable by a normal user to allow a
   client session to see the sql_trace output. If this parameter is on,
   the sql_trace will be logged as NOTICE output.


 In terms of security, is it ok to show normal users SQLs used in functions
  that are owned by other users? Users can call not-owned functions only if
  they have EXECUTE privilege on them. -- presently we can see function
  bodies from pg_proc.prosrc freely, though.

Different owner is not a problem, but SECURITY DEFINER may be.

That can be solved by turning the setting off on entry to such function,
by non-superuser.  Like we handle search_path.

-- 
marko

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-07-09 Thread Dean Rasheed 

 Just set client_min_messages = 'LOG';

True, but you would still need to be a superuser to to set the min_durations and
explain parameters. The other advantage of client_sql_trace is that you could
debug your own functions without filling up the log file. It would work better 
for
multiple users sharing the same DB.

Dean.

_
Play and win great prizes with Live Search and Kung Fu Panda
http://clk.atdmt.com/UKM/go/101719966/direct/01/
-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-07-09 Thread Dean Rasheed 

Of course you can still sort of see the SQL used in functions declared
SECURITY DEFINER, using debug_print_parse, but this would be opening
up a much more transparent way to do it.

Do I need to worry about this?

Dean


 Date: Wed, 9 Jul 2008 14:22:45 +0300
 From: [EMAIL PROTECTED]
 To: [EMAIL PROTECTED]
 Subject: Re: [HACKERS] Auto-explain patch
 CC: [EMAIL PROTECTED]; [EMAIL PROTECTED]; pgsql-hackers@postgresql.org
 
 On 7/9/08, ITAGAKI Takahiro  wrote:
  Dean Rasheed  wrote:
 * client_sql_trace = on | off - settable by a normal user to allow a
  client session to see the sql_trace output. If this parameter is on,
  the sql_trace will be logged as NOTICE output.


 In terms of security, is it ok to show normal users SQLs used in functions
  that are owned by other users? Users can call not-owned functions only if
  they have EXECUTE privilege on them. -- presently we can see function
  bodies from pg_proc.prosrc freely, though.
 
 Different owner is not a problem, but SECURITY DEFINER may be.
 
 That can be solved by turning the setting off on entry to such function,
 by non-superuser.  Like we handle search_path.
 
 -- 
 marko

_
Find the best and worst places on the planet
http://clk.atdmt.com/UKM/go/101719807/direct/01/
-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-07-09 Thread Marko Kreen 
On 7/9/08, Dean Rasheed [EMAIL PROTECTED] wrote:
  Of course you can still sort of see the SQL used in functions declared
  SECURITY DEFINER, using debug_print_parse, but this would be opening
  up a much more transparent way to do it.

  Do I need to worry about this?

If this allows to see values, then yes.  Otherwise no.

-- 
marko

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-07-09 Thread Tom Lane 
Marko Kreen [EMAIL PROTECTED] writes:
 On 7/9/08, Dean Rasheed [EMAIL PROTECTED] wrote:
 Do I need to worry about this?

 If this allows to see values, then yes.  Otherwise no.

It definitely would open a hole that doesn't exist now, which is to
see values that are inserted into an EXECUTE'd query.

regards, tom lane

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-07-09 Thread Simon Riggs 

On Wed, 2008-07-09 at 12:01 +, Dean Rasheed wrote:
  Just set client_min_messages = 'LOG';
 
 True, but you would still need to be a superuser to to set the min_durations 
 and
 explain parameters. 

No

 The other advantage of client_sql_trace is that you could
 debug your own functions without filling up the log file. It would work 
 better for
 multiple users sharing the same DB.

Not sure about that. We have debuggers and dbms_put_line already.

I think it would be better to introduce a new logging category than to
do something just specifically for this situation. 

Suggest new level=TRACE. This allows messages which are not typically
logged by server, yet are specifically requested by client. Admin has
the option to log the messages if desired.

Server log sequence is
DEBUG5, DEBUG4, DEBUG3, DEBUG2, DEBUG1, INFO, NOTICE, WARNING, ERROR,
*TRACE*, LOG, FATAL, and PANIC.

Rationale for placement: Default is LOG, so TRACE messages not logged by
default. Sometimes set to ERROR. Setting at this position allows full
system trace to be taken if required, then reset when trace complete.

Client log Sequence is
DEBUG5, DEBUG4, DEBUG3, DEBUG2, DEBUG1, LOG, NOTICE, *TRACE*, WARNING,
ERROR, FATAL, and PANIC.

Rationale for placement: many NOTICE messages are generated by various
commands, so many people can still set this off and still get TRACE
messages.

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


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-07-07 Thread Simon Riggs 

On Sun, 2008-07-06 at 17:58 +, Dean Rasheed wrote:

 OK, this one should work against CVS HEAD.

OK, still getting some offsets, but it applies.

The patch now outputs things in a useful way to avoid a flood of
information, that's good.

The code seems fine, but it doesn't link up with the other logging code
in postgres.c. That split also seems to drive the way the parameters
work, so you have another set of parameters mirroring the
log_min_duration_statement infrastructure. Fairly yuk, but I understand
why you've done this. It does however beg some serious questions about
the way we currently do logging.

The patch as it stands would produce EXPLAIN output for queries that
will never be logged, which isn't very useful. So Dean, right now I feel
this version of the patch must be rejected while we discuss how things
might work differently. Not an issue with the patch, so much as issues
with the code being patched.

So thinking about the issues we can either ignore them or tackle them:

Ignoring problem option: Rewrite this patch as an executor plugin, using
Itagaki Takahiro's new infrastructure. It's an option, but I guess Dave
will have something to say about that...

Fix problems: Having logging in two separate places is ugly and leads to
the problem of logging EXPLAINs and SQL completely separately, which
isn't very useful.

If we put all the logging code in the executor we miss out any parsing
and planning time but we can log statements and explains for SPI queries
also. 

We could move the logging of the EXPLAIN to postgres.c, but then we'd
need to make querydescs live a little longer than desirable, or we
trigger the EXPLAIN code using some guess at what the planning overhead
was, a horrible kluge.

Neither way is clean. So how do we do it?

My proposal would be to introduce some new logging statements that work
similarly to, yet as an alternative to log_min_duration_statement.

*  log_min_planner_duration - logs any statement whose planning time
exceeds the value in ms (-1 is off).
e.g. LOG  planner time: %s ms  statement: %s 

*  log_min_executor_duration - logs any execution whose execution time
exceeds the value in ms (-1 is off). We need to pass query text through
to the executor, depending upon whether its a portal's source text or an
incoming simple querystring. (This is similar, but not quite the same as
current patch's debug_explain_min_duration).
e.g. LOG  executor time: %s ms  statement: %s 

*  log_explain = on | off - logs EXPLAIN if either
log_min_executor_duration or log_min_planner_duration triggers. We
output the explain on the same line as the SQL statement, so we don't
need to play games to link up the output later. (This is similar to, but
not quite the same as current patch's debug_explain_plan).
e.g. LOG  executor time: %s ms  statement: %s 

If both log_min_executor_duration and log_min_planner_duration trigger
then we get only one log line like this:
e.g. LOG  planner time: %s ms  executor time: %s ms  statement: %s 

We should call these parameters log_xxx not debug_xxx because we want
them for production logging.

If either of these new parameters is  -1 then
log_min_duration_statement does not trigger. (Or we simply make
log_min_duration_statement control the setting of the other two
parameters).

The log messages shown above allow us to differentiate between the
reasons the SQL statement has been logged, as well as providing the
details we want.

If we do this then:

* we can log EXPLAINs for any execution, plus we will always have the
SQL for any EXPLAIN

* we can log statements that take a long time to plan, yet a short time
to execute. That can be an overhead in some cases. It also neatly
sidelines the issue of where logging takes place. (We need to be able to
track planner time, if we think we might want to introduce options to
control planner effort, topic discussed on other recent thread, not
here)

* we can log SQL for any execution, even those via SPI. That means we'll
be able to log the SQL used in functions.

We'll probably need an option to log SQL from SPI or not. Things like RI
trigger code probably doesn't need to be logged, especially if the top
level statement is, like ALTER TABLE.

This alters current performance logging, so I expect discussion.

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


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-07-06 Thread Simon Riggs 

On Thu, 2008-07-03 at 16:58 +, Dean Rasheed wrote:
 Here is an updated version of the patch

Dean,

I'm getting 4 chunks fail when trying to apply your patch onto CVS HEAD.

I'm sure its just a little bitrot. Can you update the patch please? 

Thanks,

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


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-07-06 Thread Dean Rasheed 

OK, this one should work against CVS HEAD.
 
Dean.
 Subject: Re: [HACKERS] Auto-explain patch From: [EMAIL PROTECTED] To: 
 [EMAIL PROTECTED] CC: pgsql-hackers@postgresql.org Date: Sun, 6 Jul 2008 
 16:42:55 +0100   On Thu, 2008-07-03 at 16:58 +, Dean Rasheed wrote:  
 Here is an updated version of the patch  Dean,  I'm getting 4 chunks fail 
 when trying to apply your patch onto CVS HEAD.  I'm sure its just a little 
 bitrot. Can you update the patch please?   Thanks,  --  Simon Riggs 
 www.2ndQuadrant.com PostgreSQL Training, Services and Support 
_
The John Lewis Clearance - save up to 50% with FREE delivery
http://clk.atdmt.com/UKM/go/101719806/direct/01/*** ./doc/src/sgml/config.sgml.orig 2008-03-11 16:59:09.0 +
--- ./doc/src/sgml/config.sgml  2008-07-03 14:20:15.0 +0100
***
*** 2674,2679 
--- 2674,2700 
 /listitem
/varlistentry
  
+  varlistentry id=guc-debug-explain-min-duration 
xreflabel=debug_explain_min_duration
+   termvarnamedebug_explain_min_duration/varname 
(typeinteger/type)/term
+   indexterm
+primaryvarnamedebug_explain_min_duration/ configuration 
parameter/primary
+   /indexterm
+   listitem
+para
+ This option, together with xref linkend=guc-debug-explain-plan,
+ enables logging of debug messages explaining all SQL queries which
+ run for at least the specified number of milliseconds. Setting this
+ to zero (the default) will cause all statement execution plans to be
+ explained, when xref linkend=guc-debug-explain-plan is on.
+/para
+ 
+para
+ When xref linkend=guc-debug-explain-plan if off, no statements
+ are explained, and this parameter has no effect.
+/para
+   /listitem
+  /varlistentry
+ 
   varlistentry id=guc-silent-mode xreflabel=silent_mode
termvarnamesilent_mode/varname (typeboolean/type)/term
indexterm
***
*** 2794,2799 
--- 2815,2822 
termvarnamedebug_print_rewritten/varname 
(typeboolean/type)/term
termvarnamedebug_print_plan/varname (typeboolean/type)/term
termvarnamedebug_pretty_print/varname 
(typeboolean/type)/term
+   termanchor id=guc-debug-explain-plan 
xreflabel=debug_explain_plan
+varnamedebug_explain_plan/varname (typeboolean/type)/term
indexterm
 primaryvarnamedebug_print_parse/ configuration 
parameter/primary
/indexterm
***
*** 2806,2811 
--- 2829,2837 
indexterm
 primaryvarnamedebug_pretty_print/ configuration 
parameter/primary
/indexterm
+   indexterm
+primaryvarnamedebug_explain_plan/ configuration 
parameter/primary
+   /indexterm
listitem
 para
  These parameters enable various debugging output to be emitted.
***
*** 2813,2824 
  the resulting parse tree, the query rewriter output, or the
  execution plan.  varnamedebug_pretty_print/varname indents
  these displays to produce a more readable but much longer
! output format.  varnameclient_min_messages/varname or
  varnamelog_min_messages/varname must be
  literalDEBUG1/literal or lower to actually send this output
  to the client or the server log, respectively.
  These parameters are off by default.
 /para
/listitem
   /varlistentry
  
--- 2839,2867 
  the resulting parse tree, the query rewriter output, or the
  execution plan.  varnamedebug_pretty_print/varname indents
  these displays to produce a more readable but much longer
! output format.  varnamedebug_explain_plan/varname prints
! the plan for each executed query in the same format as
! commandEXPLAIN ANALYZE/. This includes queries executed from
! within functions.  varnameclient_min_messages/varname or
  varnamelog_min_messages/varname must be
  literalDEBUG1/literal or lower to actually send this output
  to the client or the server log, respectively.
  These parameters are off by default.
 /para
+ 
+note
+ para
+  The reports produced by varnamedebug_explain_plan/varname
+  are produced at a lower level in the database, as each query
+  is executed, including queries executed from functions, so
+  the output may be more verbose that of commandEXPLAIN ANALYZE/
+  and the timings may differ. When this option is used together
+  with xref linkend=guc-debug-explain-min-duration, all queries
+  will be instrumented, but only those which run for at least the
+  specified number of milliseconds will have their execution plans
+  reported. 
+ /para
+/note
/listitem
   /varlistentry
  
*** ./src/backend

Re: [HACKERS] Auto-explain patch

2008-07-03 Thread Dean Rasheed 

Here is an updated version of the patch, with a debug_explain_min_duration
parameter to allow explaining of just slow-running queries. I've also 
incorporated
a couple of Simon Riggs' suggestions for formatting the output better.

Do I need to post this to -patches, or is that now obsolete?

Regards, Dean


 From: [EMAIL PROTECTED]
 To: [EMAIL PROTECTED]
 CC: pgsql-hackers@postgresql.org
 Subject: RE: [HACKERS] Auto-explain patch
 Date: Wed, 2 Jul 2008 19:42:06 +


 Its certainly not useful to *me* in its current form. It would
 produce way to much (usless) output. However if it were tied to
 log_min_duration_statement so I get auto explains for long running
 queries... That would be very useful indeed. Even if it has to
 explain everything just to toss out the explain if it did not meet
 log_min_duration_statement. Unless I missed something and thats
 exactly what it does?

 Thanks for the feedback. I agree, it does need a way to limit the
 output, and target just the slow-running queries.

 I also remember now the problem I had last time:- since this debug
 output is produced at a lower level than the other statement logging
 (so it can explain *all* SQL executed, not just top-level statements), it
 is difficult to control using the normal statement logging parameters.

 It would be easy to add another parameter, debug_explain_min_duration,
 specific to this option, to limit it to slow low-level queries.

 This would allow setting debug_explain_min_duration to be smaller than
 log_min_duration_statement, which makes sense, since the latter
 controls logging of top-level statements which may result in multiple
 low-level queries.

 Doing it this way would mean instrumenting all queries, but only
 explaining the slow ones, when debug_explain_plan is on.
 I'll have a play and see how it goes...

 Regards, Dean

 _
 Live Search Charades - guess correctly and find hidden videos
 http://www.searchcharades.com/

_
The next generation of Windows Live is here
http://www.windowslive.co.uk/get-live*** ./doc/src/sgml/config.sgml.orig	2008-03-11 16:59:09.0 +
--- ./doc/src/sgml/config.sgml	2008-07-03 14:20:15.0 +0100
***
*** 2674,2679 
--- 2674,2700 
 /listitem
/varlistentry
  
+  varlistentry id=guc-debug-explain-min-duration xreflabel=debug_explain_min_duration
+   termvarnamedebug_explain_min_duration/varname (typeinteger/type)/term
+   indexterm
+primaryvarnamedebug_explain_min_duration/ configuration parameter/primary
+   /indexterm
+   listitem
+para
+ This option, together with xref linkend=guc-debug-explain-plan,
+ enables logging of debug messages explaining all SQL queries which
+ run for at least the specified number of milliseconds. Setting this
+ to zero (the default) will cause all statement execution plans to be
+ explained, when xref linkend=guc-debug-explain-plan is on.
+/para
+ 
+para
+ When xref linkend=guc-debug-explain-plan if off, no statements
+ are explained, and this parameter has no effect.
+/para
+   /listitem
+  /varlistentry
+ 
   varlistentry id=guc-silent-mode xreflabel=silent_mode
termvarnamesilent_mode/varname (typeboolean/type)/term
indexterm
***
*** 2794,2799 
--- 2815,2822 
termvarnamedebug_print_rewritten/varname (typeboolean/type)/term
termvarnamedebug_print_plan/varname (typeboolean/type)/term
termvarnamedebug_pretty_print/varname (typeboolean/type)/term
+   termanchor id=guc-debug-explain-plan xreflabel=debug_explain_plan
+varnamedebug_explain_plan/varname (typeboolean/type)/term
indexterm
 primaryvarnamedebug_print_parse/ configuration parameter/primary
/indexterm
***
*** 2806,2811 
--- 2829,2837 
indexterm
 primaryvarnamedebug_pretty_print/ configuration parameter/primary
/indexterm
+   indexterm
+primaryvarnamedebug_explain_plan/ configuration parameter/primary
+   /indexterm
listitem
 para
  These parameters enable various debugging output to be emitted.
***
*** 2813,2824 
  the resulting parse tree, the query rewriter output, or the
  execution plan.  varnamedebug_pretty_print/varname indents
  these displays to produce a more readable but much longer
! output format.  varnameclient_min_messages/varname or
  varnamelog_min_messages/varname must be
  literalDEBUG1/literal or lower to actually send this output
  to the client or the server log, respectively.
  These parameters are off by default.
 /para
/listitem
   /varlistentry
  
--- 2839,2867

Re: [HACKERS] Auto-explain patch

2008-07-03 Thread Alex Hunsaker 
On Thu, Jul 3, 2008 at 10:58 AM, Dean Rasheed [EMAIL PROTECTED] wrote:

 Here is an updated version of the patch, with a debug_explain_min_duration
 parameter to allow explaining of just slow-running queries. I've also 
 incorporated
 a couple of Simon Riggs' suggestions for formatting the output better.

 Do I need to post this to -patches, or is that now obsolete?

Yes its obsolete now, instead add it to July's commit fest at
http://wiki.postgresql.org/wiki/CommitFest:July.

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-07-02 Thread Dean Rasheed 

 Its certainly not useful to *me* in its current form. It would
 produce way to much (usless) output. However if it were tied to
 log_min_duration_statement so I get auto explains for long running
 queries... That would be very useful indeed. Even if it has to
 explain everything just to toss out the explain if it did not meet
 log_min_duration_statement. Unless I missed something and thats
 exactly what it does?

Thanks for the feedback. I agree, it does need a way to limit the
output, and target just the slow-running queries.

I also remember now the problem I had last time:- since this debug
output is produced at a lower level than the other statement logging
(so it can explain *all* SQL executed, not just top-level statements), it
is difficult to control using the normal statement logging parameters.

It would be easy to add another parameter, debug_explain_min_duration,
specific to this option, to limit it to slow low-level queries.

This would allow setting debug_explain_min_duration to be smaller than
log_min_duration_statement, which makes sense, since the latter
controls logging of top-level statements which may result in multiple
low-level queries.

Doing it this way would mean instrumenting all queries, but only
explaining the slow ones, when debug_explain_plan is on.
I'll have a play and see how it goes...

Regards, Dean

_
Live Search Charades - guess correctly and find hidden videos
http://www.searchcharades.com/
-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-06-30 Thread Dean Rasheed 

Hi,

This is a small patch I posted a few months back, and then kinda forgot
about / got distracted with other things.

Is there any interest in this? If so I am willing to put more work into
it, if people like it or have suggested improvements. Otherwise I'll let it
drop.

Here's what is does:

As it stands, basically it's just another debug parameter, called
debug_explain_plan, similar to debug_print_plan, except that the
output is in the form of EXPLAIN ANALYSE.

The main advantage it offers over a standard EXPLAIN ANALYSE is that
it explains *all* SQL executed, including any from within stored
prodecures and triggers, so it is quite useful for debugging these.

With a suitable logging level, it can also be used to produce very
verbose logfile output to help spot any inefficient database access by
other applications.

Example usage:

test=# SET debug_explain_plan=on;
SET
test=# SET client_min_messages=debug1;
SET
test=# CREATE TABLE foo(a int primary key);
NOTICE:  CREATE TABLE / PRIMARY KEY will create implicit index foo_pkey for 
table foo
CREATE TABLE
test=# INSERT INTO foo VALUES (1), (2), (3), (4), (5);
DEBUG:  --- query plan ---
DETAIL:  Values Scan on *VALUES*  (cost=0.00..0.06 rows=5 width=4) (actual 
time=0.001..0.006 rows=5 loops=1)
Query runtime: 0.329 ms
INSERT 0 5
test=# CREATE FUNCTION foo() RETURNS int as 'select max(a) from foo;' LANGUAGE 
SQL STABLE;
CREATE FUNCTION
test=# SELECT * FROM foo WHERE a=foo();
DEBUG:  --- query plan ---
DETAIL:  Result  (cost=0.04..0.05 rows=1 width=0) (actual time=0.044..0.044 
rows=1 loops=1)
  InitPlan
-  Limit  (cost=0.00..0.04 rows=1 width=4) (actual time=0.032..0.034 
rows=1 loops=1)
  -  Index Scan Backward using foo_pkey on foo  (cost=0.00..84.25 
rows=2400 width=4) (actual time=0.025..0.025 rows=1 loops=1)
Filter: (a IS NOT NULL)
Query runtime: 0.050 ms
CONTEXT:  SQL function foo statement 1
DEBUG:  --- query plan ---
DETAIL:  Result  (cost=0.04..0.05 rows=1 width=0) (actual time=0.037..0.037 
rows=1 loops=1)
  InitPlan
-  Limit  (cost=0.00..0.04 rows=1 width=4) (actual time=0.027..0.029 
rows=1 loops=1)
  -  Index Scan Backward using foo_pkey on foo  (cost=0.00..84.25 
rows=2400 width=4) (actual time=0.021..0.021 rows=1 loops=1)
Filter: (a IS NOT NULL)
Query runtime: 0.044 ms
CONTEXT:  SQL function foo statement 1
DEBUG:  --- query plan ---
DETAIL:  Index Scan using foo_pkey on foo  (cost=0.25..8.52 rows=1 width=4) 
(actual time=1.638..1.642 rows=1 loops=1)
  Index Cond: (a = foo())
Query runtime: 1.686 ms
 a
---
 5
(1 row)

test=# EXPLAIN SELECT * FROM foo WHERE a=foo();
DEBUG:  --- query plan ---
DETAIL:  Result  (cost=0.04..0.05 rows=1 width=0) (actual time=0.012..0.012 
rows=1 loops=1)
  InitPlan
-  Limit  (cost=0.00..0.04 rows=1 width=4) (actual time=0.011..0.011 
rows=1 loops=1)
  -  Index Scan Backward using foo_pkey on foo  (cost=0.00..84.25 
rows=2400 width=4) (actual time=0.010..0.010 rows=1 loops=1)
Filter: (a IS NOT NULL)
Query runtime: 0.014 ms
CONTEXT:  SQL function foo statement 1
 QUERY PLAN

 Index Scan using foo_pkey on foo  (cost=0.25..8.52 rows=1 width=4)
   Index Cond: (a = foo())
(2 rows)

(The last example shows foo() being called during the planning of this
query, which explains why it is called twice during the previous execution)

Simon Riggs reviewed this last time and said that what this patch
currently does is probably not exactly what is wanted for PostgreSQL.
Possible improvements might be to integrate this with the EXPLAIN
command (eg. EXPLAIN TRACE query) and have a separate parameter
(log_explain) for logging purposes.

Comments?

Regards, Dean

_
Live Search Charades - guess correctly and find hidden videos
http://www.searchcharades.com/*** ./doc/src/sgml/config.sgml.orig	Sun Jan 27 19:12:28 2008
--- ./doc/src/sgml/config.sgml	Sun Jan 27 21:58:32 2008
***
*** 2790,2795 
--- 2790,2796 
termvarnamedebug_print_rewritten/varname (typeboolean/type)/term
termvarnamedebug_print_plan/varname (typeboolean/type)/term
termvarnamedebug_pretty_print/varname (typeboolean/type)/term
+   termvarnamedebug_explain_plan/varname (typeboolean/type)/term
indexterm
 primaryvarnamedebug_print_parse/ configuration parameter/primary
/indexterm
***
*** 2802,2807 
--- 2803,2811 
indexterm
 primaryvarnamedebug_pretty_print/ configuration parameter/primary
/indexterm
+   indexterm
+primaryvarnamedebug_explain_plan/ configuration parameter/primary
+   /indexterm
listitem
 para
  These

Re: [HACKERS] Auto-explain patch

2008-06-30 Thread Marko Kreen 
On 6/30/08, Dean Rasheed [EMAIL PROTECTED] wrote:
  This is a small patch I posted a few months back, and then kinda forgot
  about / got distracted with other things.

  Is there any interest in this? If so I am willing to put more work into
  it, if people like it or have suggested improvements. Otherwise I'll let it
  drop.

+1 for including it in whatever form.  It is useful.

We actually already use in live settings (8.2 / 8,3).

  (The last example shows foo() being called during the planning of this
  query, which explains why it is called twice during the previous execution)

  Simon Riggs reviewed this last time and said that what this patch
  currently does is probably not exactly what is wanted for PostgreSQL.
  Possible improvements might be to integrate this with the EXPLAIN
  command (eg. EXPLAIN TRACE query) and have a separate parameter
  (log_explain) for logging purposes.

I don't have strong opinion either way,  It seems its more question
on style than any technical details.  Just that plain EXPLAN MORE is
not enough, it would bo good have a way to turn it on in global/session
level for all queries.

-- 
marko

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Auto-explain patch

2008-06-30 Thread Alex Hunsaker 
On Mon, Jun 30, 2008 at 6:34 AM, Dean Rasheed [EMAIL PROTECTED] wrote:

 Hi,

 This is a small patch I posted a few months back, and then kinda forgot
 about / got distracted with other things.

 Is there any interest in this? If so I am willing to put more work into
 it, if people like it or have suggested improvements. Otherwise I'll let it
 drop.

 Here's what is does:

 As it stands, basically it's just another debug parameter, called
 debug_explain_plan, similar to debug_print_plan, except that the
 output is in the form of EXPLAIN ANALYSE.

snip

 Simon Riggs reviewed this last time and said that what this patch
 currently does is probably not exactly what is wanted for PostgreSQL.
 Possible improvements might be to integrate this with the EXPLAIN
 command (eg. EXPLAIN TRACE query) and have a separate parameter
 (log_explain) for logging purposes.

 Comments?

Its certainly not useful to *me* in its current form.  It would
produce way to much (usless) output.  However if it were tied to
log_min_duration_statement so I get auto explains for long running
queries... That would be very useful indeed.  Even if it has to
explain everything just to toss out the explain if it did not meet
log_min_duration_statement.  Unless I missed something and thats
exactly what it does?

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers