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 +0000
>
>
>> 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.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 printNodes; /* do nodeToString() too */
- 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_scan_qual(List *qual, const char *qlabel,
int scanrelid, Plan *outer_plan, Plan *inner_plan,
StringInfo str, int indent, ExplainState *es);
--- 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"
typedef struct evalPlanQual
***************
*** 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->printNodes = 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_rewritten = false;
bool Debug_pretty_print = false;
bool Explain_pretty_print = true;
+ 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 printNodes; /* do nodeToString() too */
+ 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_rewritten;
extern bool Debug_pretty_print;
extern bool Explain_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
