This is the patch allows logging of the explain plan for each query run, as
described here:
http://archives.postgresql.org/pgsql-performance/2008-01/msg00245.php
I hope this is useful.
Dean.
_________________________________________________________________
Telly addicts unite!
http://www.searchgamesbox.com/tvtown.shtml
*** ./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 ----
<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><varname>debug_explain_plan</varname> (<type>boolean</type>)</term>
<indexterm>
<primary><varname>debug_print_parse</> configuration parameter</primary>
</indexterm>
***************
*** 2802,2807 ****
--- 2803,2811 ----
<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.
***************
*** 2809,2820 ****
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>
--- 2813,2837 ----
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.
+ </para>
+ </note>
</listitem>
</varlistentry>
*** ./src/backend/commands/explain.c.orig Tue Jan 1 19:45:50 2008
--- ./src/backend/commands/explain.c Sat Jan 26 11:55:54 2008
***************
*** 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 Tue Jan 1 19:45:50 2008
--- ./src/backend/executor/execMain.c Sat Jan 26 14:34:26 2008
***************
*** 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,198 ----
}
/*
+ * If we are explaining all queries, enable instrumentation
+ */
+ if (Debug_explain_plan)
+ queryDesc->doInstrument = true;
+
+ /*
* Copy other important information into the EState
*/
estate->es_snapshot = queryDesc->snapshot;
***************
*** 227,232 ****
--- 235,243 ----
bool sendTuples;
TupleTableSlot *result;
MemoryContext oldcontext;
+ bool explainPlan = Debug_explain_plan;
+ instr_time starttime;
+ double totaltime;
/* sanity checks */
Assert(queryDesc != NULL);
***************
*** 236,241 ****
--- 247,263 ----
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);
***************
*** 278,283 ****
--- 300,340 ----
(*dest->rShutdown) (dest);
MemoryContextSwitchTo(oldcontext);
+
+ /*
+ * If explaining all queries, log the execution plan using
+ * the same format as EXPLAIN ANALYSE
+ */
+ if (explainPlan)
+ {
+ ExplainState *es;
+ StringInfoData buf;
+
+ totaltime = elapsed_time(&starttime);
+
+ 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 -------------------"),
+ errdetail("%s", buf.data)));
+
+ pfree(buf.data);
+ pfree(es);
+ }
return result;
}
*** ./src/backend/utils/misc/guc.c.orig Sun Jan 27 19:12:28 2008
--- ./src/backend/utils/misc/guc.c Sun Jan 27 21:52:58 2008
***************
*** 193,198 ****
--- 193,199 ----
bool Debug_print_rewritten = false;
bool Debug_pretty_print = false;
bool Explain_pretty_print = true;
+ bool Debug_explain_plan = false;
bool log_parser_stats = false;
bool log_planner_stats = false;
***************
*** 682,687 ****
--- 683,696 ----
NULL
},
&Debug_pretty_print,
+ 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
},
{
*** ./src/backend/utils/misc/postgresql.conf.sample.orig Sun Jan 27 19:12:28 2008
--- ./src/backend/utils/misc/postgresql.conf.sample Sun Jan 27 21:54:26 2008
***************
*** 323,328 ****
--- 323,329 ----
#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 Tue Jan 1 19:45:58 2008
--- ./src/include/commands/explain.h Sat Jan 26 11:53:48 2008
***************
*** 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,
***************
*** 40,44 ****
--- 51,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 Tue Jan 1 19:46:00 2008
--- ./src/include/utils/guc.h Sat Jan 26 11:51:42 2008
***************
*** 117,122 ****
--- 117,123 ----
extern bool Debug_print_rewritten;
extern bool Debug_pretty_print;
extern bool Explain_pretty_print;
+ extern bool Debug_explain_plan;
extern bool log_parser_stats;
extern bool log_planner_stats;
---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match
