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 +0000, 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.000000000 +0000
--- ./doc/src/sgml/config.sgml 2008-07-03 14:20:15.000000000 +0100
***************
*** 2674,2679 ****
--- 2674,2700 ----
</listitem>
</varlistentry>
+ <varlistentry id="guc-debug-explain-min-duration"
xreflabel="debug_explain_min_duration">
+ <term><varname>debug_explain_min_duration</varname>
(<type>integer</type>)</term>
+ <indexterm>
+ <primary><varname>debug_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">
<term><varname>silent_mode</varname> (<type>boolean</type>)</term>
<indexterm>
***************
*** 2794,2799 ****
--- 2815,2822 ----
<term><varname>debug_print_rewritten</varname>
(<type>boolean</type>)</term>
<term><varname>debug_print_plan</varname> (<type>boolean</type>)</term>
<term><varname>debug_pretty_print</varname>
(<type>boolean</type>)</term>
+ <term><anchor id="guc-debug-explain-plan"
xreflabel="debug_explain_plan">
+ <varname>debug_explain_plan</varname> (<type>boolean</type>)</term>
<indexterm>
<primary><varname>debug_print_parse</> configuration
parameter</primary>
</indexterm>
***************
*** 2806,2811 ****
--- 2829,2837 ----
<indexterm>
<primary><varname>debug_pretty_print</> configuration
parameter</primary>
</indexterm>
+ <indexterm>
+ <primary><varname>debug_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. <varname>debug_pretty_print</varname> indents
these displays to produce a more readable but much longer
! output format. <varname>client_min_messages</varname> or
<varname>log_min_messages</varname> must be
<literal>DEBUG1</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. <varname>debug_pretty_print</varname> indents
these displays to produce a more readable but much longer
! output format. <varname>debug_explain_plan</varname> prints
! the plan for each executed query in the same format as
! <command>EXPLAIN ANALYZE</>. This includes queries executed from
! within functions. <varname>client_min_messages</varname> or
<varname>log_min_messages</varname> must be
<literal>DEBUG1</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 <varname>debug_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 <command>EXPLAIN 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/commands/explain.c.orig 2008-01-01 19:45:49.000000000
+0000
--- ./src/backend/commands/explain.c 2008-06-27 12:06:19.000000000 +0100
***************
*** 39,65 ****
/* Hook for plugins to get control in explain_get_index_name() */
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,
--- 39,49 ----
***************
*** 402,408 ****
}
/* Compute elapsed time in seconds since given timestamp */
! static double
elapsed_time(instr_time *starttime)
{
instr_time endtime;
--- 386,392 ----
}
/* Compute elapsed time in seconds since given timestamp */
! double
elapsed_time(instr_time *starttime)
{
instr_time endtime;
***************
*** 436,442 ****
* 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,
--- 420,426 ----
* 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-04-21 04:49:51.000000000
+0100
--- ./src/backend/executor/execMain.c 2008-07-03 09:49:52.000000000 +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 "utils/acl.h"
#include "utils/lsyscache.h"
#include "utils/memutils.h"
+ #include "utils/guc.h"
#include "utils/snapmgr.h"
#include "utils/tqual.h"
***************
*** 185,190 ****
--- 187,200 ----
}
/*
+ * If we are explaining all queries, enable instrumentation.
+ * Even if we are only explaining the slow queries, we still
+ * need to instrument them all.
+ */
+ if (Debug_explain_plan)
+ queryDesc->doInstrument = true;
+
+ /*
* Copy other important information into the EState
*/
estate->es_snapshot = queryDesc->snapshot;
***************
*** 227,232 ****
--- 237,245 ----
bool sendTuples;
TupleTableSlot *result;
MemoryContext oldcontext;
+ bool explainPlan = Debug_explain_plan;
+ instr_time starttime;
+ double totaltime;
/* sanity checks */
Assert(queryDesc != NULL);
***************
*** 236,241 ****
--- 249,265 ----
Assert(estate != NULL);
/*
+ * If explaining all queries, record the start time before running
+ * the query. This is not quite the same as EXPLAIN ANALYSE, which
+ * starts timing before ExecutorStart(). Here we are only timing
+ * how long the query takes to run, once initialised and also
+ * excluding any triggers (which may themselves run queries which
+ * will be instrumented separately).
+ */
+ if (explainPlan)
+ INSTR_TIME_SET_CURRENT(starttime);
+
+ /*
* Switch into per-query memory context
*/
oldcontext = MemoryContextSwitchTo(estate->es_query_cxt);
***************
*** 279,284 ****
--- 303,341 ----
MemoryContextSwitchTo(oldcontext);
+ /*
+ * If explaining queries and this one was slow enough, log the
+ * execution plan using the same format as EXPLAIN ANALYSE
+ */
+ totaltime = elapsed_time(&starttime);
+ if (explainPlan && totaltime * 1000 >= Debug_explain_min_duration)
+ {
+ ExplainState *es;
+ StringInfoData buf;
+
+ es = (ExplainState *) palloc0(sizeof(ExplainState));
+
+ es->printTList = false;
+ es->printAnalyze = true;
+ es->pstmt = queryDesc->plannedstmt;
+ es->rtable = queryDesc->plannedstmt->rtable;
+
+ initStringInfo(&buf);
+ explain_outNode(&buf,
+
queryDesc->plannedstmt->planTree,
+ queryDesc->planstate,
+ NULL, 0, es);
+
+ appendStringInfo(&buf, "Query runtime: %.3f ms",
+ 1000.0 * totaltime);
+
+ ereport(DEBUG1,
+ (errmsg("Query plan:\n%s", buf.data)));
+
+ pfree(buf.data);
+ pfree(es);
+ }
+
return result;
}
*** ./src/backend/utils/misc/guc.c.orig 2008-05-26 19:54:36.000000000 +0100
--- ./src/backend/utils/misc/guc.c 2008-07-03 09:49:30.000000000 +0100
***************
*** 194,199 ****
--- 194,201 ----
bool Debug_print_parse = false;
bool Debug_print_rewritten = false;
bool Debug_pretty_print = false;
+ bool Debug_explain_plan = false;
+ int Debug_explain_min_duration = 0;
bool log_parser_stats = false;
bool log_planner_stats = false;
***************
*** 686,691 ****
--- 688,701 ----
false, NULL, NULL
},
{
+ {"debug_explain_plan", PGC_USERSET, LOGGING_WHAT,
+ gettext_noop("Explains the execution plan to server
log."),
+ NULL
+ },
+ &Debug_explain_plan,
+ false, NULL, NULL
+ },
+ {
{"log_parser_stats", PGC_SUSET, STATS_MONITORING,
gettext_noop("Writes parser performance statistics to
the server log."),
NULL
***************
*** 1567,1572 ****
--- 1577,1593 ----
},
{
+ {"debug_explain_min_duration", PGC_USERSET, LOGGING_WHEN,
+ gettext_noop("Sets the minimum execution time above
which "
+ "statements will be
explained."),
+ gettext_noop("0 causes all statements to be
explained."),
+ GUC_UNIT_MS
+ },
+ &Debug_explain_min_duration,
+ 0, 0, INT_MAX / 1000, NULL, NULL
+ },
+
+ {
{"log_autovacuum_min_duration", PGC_SIGHUP, LOGGING_WHAT,
gettext_noop("Sets the minimum execution time above
which "
"autovacuum actions will be
logged."),
*** ./src/backend/utils/misc/postgresql.conf.sample.orig 2008-01-30
18:35:55.000000000 +0000
--- ./src/backend/utils/misc/postgresql.conf.sample 2008-07-03
10:08:57.000000000 +0100
***************
*** 313,318 ****
--- 313,322 ----
# and their durations, > 0 logs only
# statements running at least this time.
+ #debug_explain_min_duration = 0 # limits the output of
debug_explain_plan
+ # to queries which run for at least the
+ # the specified number of milliseconds.
+
#silent_mode = off # DO NOT USE without syslog or
# logging_collector
# (change requires restart)
***************
*** 323,328 ****
--- 327,333 ----
#debug_print_rewritten = off
#debug_print_plan = off
#debug_pretty_print = off
+ #debug_explain_plan = off
#log_checkpoints = off
#log_connections = off
#log_disconnections = off
*** ./src/include/commands/explain.h.orig 2008-01-01 19:45:57.000000000
+0000
--- ./src/include/commands/explain.h 2008-06-27 12:06:19.000000000 +0100
***************
*** 14,19 ****
--- 14,30 ----
#define EXPLAIN_H
#include "executor/executor.h"
+ #include "executor/instrument.h"
+
+ 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;
/* Hook for plugins to get control in ExplainOneQuery() */
typedef void (*ExplainOneQuery_hook_type) (Query *query,
***************
*** 41,44 ****
--- 52,62 ----
extern void ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
ExplainStmt *stmt, TupOutputState *tstate);
+ extern void explain_outNode(StringInfo str,
+ Plan *plan, PlanState *planstate,
+ Plan *outer_plan,
+ int indent, ExplainState *es);
+
+ extern double elapsed_time(instr_time *starttime);
+
#endif /* EXPLAIN_H */
*** ./src/include/utils/guc.h.orig 2008-01-01 19:45:59.000000000 +0000
--- ./src/include/utils/guc.h 2008-07-02 20:46:55.000000000 +0100
***************
*** 117,122 ****
--- 117,124 ----
extern bool Debug_print_parse;
extern bool Debug_print_rewritten;
extern bool Debug_pretty_print;
+ extern bool Debug_explain_plan;
+ extern int Debug_explain_min_duration;
extern bool log_parser_stats;
extern bool log_planner_stats;
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
