*** ./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;