Re: Auto-explain patch

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

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

*** ./src/backend/commands/copy.c.orig	2008-07-09 16:14:54.000000000 +0100
--- ./src/backend/commands/copy.c	2008-07-09 16:15:54.000000000 +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.000000000 +0100
--- ./src/backend/commands/explain.c	2008-07-09 16:14:28.000000000 +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.000000000 +0100
--- ./src/backend/executor/execMain.c	2008-07-10 10:34:26.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 "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))
+ 		queryDesc->doInstrument = true;
+ 
+ 	/*
  	 * Copy other important information into the EState
  	 */
  	estate->es_snapshot = RegisterSnapshot(queryDesc->snapshot);
***************
*** 226,231 ****
--- 236,244 ----
  	bool		sendTuples;
  	TupleTableSlot *result;
  	MemoryContext oldcontext;
+ 	bool		time_planner = trace_min_planner_duration > -1;
+ 	bool		time_executor = trace_min_executor_duration > -1;
+ 	instr_time	starttime;
  
  	/* sanity checks */
  	Assert(queryDesc != NULL);
***************
*** 235,240 ****
--- 248,260 ----
  	Assert(estate != NULL);
  
  	/*
+ 	 * If tracing slow-running queries, record the start time before
+ 	 * running the query
+ 	 */
+ 	if (time_executor)
+ 		INSTR_TIME_SET_CURRENT(starttime);
+ 
+ 	/*
  	 * Switch into per-query memory context
  	 */
  	oldcontext = MemoryContextSwitchTo(estate->es_query_cxt);
***************
*** 278,283 ****
--- 298,378 ----
  
  	MemoryContextSwitchTo(oldcontext);
  
+ 	/*
+ 	 * If tracing slow queries, then we should log planner time,
+ 	 * execution time, statement SQL and execution time
+ 	 */
+ 	if (time_planner || time_executor)
+ 	{
+ 		bool log_stmt = false;
+ 		StringInfoData buf;
+ 		double planner_time_ms;
+ 		double executor_time_ms;
+ 
+ 		initStringInfo(&buf);
+ 
+ 		/* Log planner time if appropriate */
+ 		if (time_planner)
+ 		{
+ 			planner_time_ms = queryDesc->plannedstmt->planner_time * 1000.0;
+ 			if (planner_time_ms >= trace_min_planner_duration)
+ 			{
+ 				appendStringInfo(&buf, "planner time: %.3f ms  ",
+ 								 planner_time_ms);
+ 				log_stmt = true;
+ 			}
+ 			/* Don't log again, unless re-planned and still slow */
+ 			queryDesc->plannedstmt->planner_time = 0.0;
+ 		}
+ 
+ 		/* Log execution time if appropriate */
+ 		if (time_executor)
+ 		{
+ 			executor_time_ms = elapsed_time(&starttime) * 1000.0;
+ 			if (executor_time_ms >= trace_min_executor_duration)
+ 			{
+ 				appendStringInfo(&buf, "executor time: %.3f ms  ",
+ 								 executor_time_ms);
+ 				log_stmt = true;
+ 			}
+ 		}
+ 
+ 		/*
+ 		 * Only if either of the above caused the statement to be logged,
+ 		 * then log the statement SQL and maybe its execution plan
+ 		 */
+ 		if (log_stmt)
+ 		{
+ 			if (queryDesc->plannedstmt->query_string)
+ 				appendStringInfo(&buf, "statement: %s",
+ 								 queryDesc->plannedstmt->query_string);
+ 
+ 			if (trace_explain_plan)
+ 			{
+ 				ExplainState *es;
+ 
+ 				es = (ExplainState *) palloc0(sizeof(ExplainState));
+ 
+ 				es->printTList = false;
+ 				es->printAnalyze = true;
+ 				es->pstmt = queryDesc->plannedstmt;
+ 				es->rtable = queryDesc->plannedstmt->rtable;
+ 
+ 				appendStringInfo(&buf, "  plan:\n");
+ 				explain_outNode(&buf,
+ 								queryDesc->plannedstmt->planTree,
+ 								queryDesc->planstate,
+ 								NULL, 0, es);
+ 				pfree(es);
+ 			}
+ 
+ 			/* Finally log this trace report */
+ 			ereport(TRACE, (errmsg(buf.data)));
+ 		}
+ 
+ 		pfree(buf.data);
+ 	}
+ 
  	return result;
  }
  
*** ./src/backend/executor/spi.c.orig	2008-07-09 15:52:10.000000000 +0100
--- ./src/backend/executor/spi.c	2008-07-09 15:58:20.000000000 +0100
***************
*** 1764,1769 ****
--- 1764,1770 ----
  				else
  					snap = InvalidSnapshot;
  
+ 				((PlannedStmt *)stmt)->query_string = plansource->query_string;
  				qdesc = CreateQueryDesc((PlannedStmt *) stmt,
  										snap, crosscheck_snapshot,
  										dest,
*** ./src/backend/optimizer/plan/planner.c.orig	2008-07-09 11:38:06.000000000 +0100
--- ./src/backend/optimizer/plan/planner.c	2008-07-10 10:16:49.000000000 +0100
***************
*** 18,24 ****
--- 18,26 ----
  #include <limits.h>
  
  #include "catalog/pg_operator.h"
+ #include "commands/explain.h"
  #include "executor/executor.h"
+ #include "executor/instrument.h"
  #include "executor/nodeAgg.h"
  #include "miscadmin.h"
  #include "nodes/makefuncs.h"
***************
*** 38,43 ****
--- 40,46 ----
  #include "parser/parse_expr.h"
  #include "parser/parse_oper.h"
  #include "parser/parsetree.h"
+ #include "utils/guc.h"
  #include "utils/lsyscache.h"
  #include "utils/syscache.h"
  
***************
*** 99,109 ****
--- 102,128 ----
  planner(Query *parse, int cursorOptions, ParamListInfo boundParams)
  {
  	PlannedStmt *result;
+ 	instr_time starttime;
  
+ 	/*
+ 	 * If we are tracing statements which take a long time to plan,
+ 	 * then time how long this takes.
+ 	 */
+ 	if (trace_min_planner_duration > -1)
+ 		INSTR_TIME_SET_CURRENT(starttime);
+ 
+ 	/* Plan the query */
  	if (planner_hook)
  		result = (*planner_hook) (parse, cursorOptions, boundParams);
  	else
  		result = standard_planner(parse, cursorOptions, boundParams);
+ 
+ 	/* Record how long it took, if appropriate */
+ 	if (trace_min_planner_duration)
+ 		result->planner_time = elapsed_time(&starttime);
+ 	else
+ 		result->planner_time = 0.0;
+ 
  	return result;
  }
  
*** ./src/backend/tcop/pquery.c.orig	2008-07-09 16:58:07.000000000 +0100
--- ./src/backend/tcop/pquery.c	2008-07-10 10:33:52.000000000 +0100
***************
*** 895,900 ****
--- 895,903 ----
  	 */
  	queryDesc = PortalGetQueryDesc(portal);
  
+ 	if (queryDesc)
+ 		queryDesc->plannedstmt->query_string = portal->sourceText;
+ 
  	/* Caller messed up if we have neither a ready query nor held data. */
  	Assert(queryDesc || portal->holdStore);
  
***************
*** 1236,1241 ****
--- 1239,1245 ----
  			 * process a plannable query.
  			 */
  			PlannedStmt *pstmt = (PlannedStmt *) stmt;
+ 			pstmt->query_string = portal->sourceText;
  
  			if (log_executor_stats)
  				ResetUsage();
*** ./src/backend/utils/error/elog.c.orig	2008-07-10 09:27:12.000000000 +0100
--- ./src/backend/utils/error/elog.c	2008-07-10 10:09:11.000000000 +0100
***************
*** 1428,1433 ****
--- 1428,1434 ----
  		case COMMERROR:
  		case INFO:
  		case NOTICE:
+ 		case TRACE:
  			eventlevel = EVENTLOG_INFORMATION_TYPE;
  			break;
  		case WARNING:
***************
*** 2027,2032 ****
--- 2028,2034 ----
  				syslog_level = LOG_INFO;
  				break;
  			case NOTICE:
+ 			case TRACE:
  			case WARNING:
  				syslog_level = LOG_NOTICE;
  				break;
***************
*** 2416,2421 ****
--- 2418,2426 ----
  		case NOTICE:
  			prefix = _("NOTICE");
  			break;
+ 		case TRACE:
+ 			prefix = _("TRACE");
+ 			break;
  		case WARNING:
  			prefix = _("WARNING");
  			break;
***************
*** 2506,2511 ****
--- 2511,2519 ----
   * between ERROR and FATAL.  Generally this is the right thing for testing
   * whether a message should go to the postmaster log, whereas a simple >=
   * test is correct for testing whether the message should go to the client.
+  *
+  * Similarly, TRACE is considered to be between ERROR and LOG (<FATAL)
+  * for the purposes of the postmaster log, and so is not output by default.
   */
  static bool
  is_log_level_output(int elevel, int log_min_level)
***************
*** 2517,2523 ****
  	}
  	else if (log_min_level == LOG)
  	{
! 		/* elevel != LOG */
  		if (elevel >= FATAL)
  			return true;
  	}
--- 2525,2543 ----
  	}
  	else if (log_min_level == LOG)
  	{
! 		/* elevel != LOG or COMMERROR */
! 		if (elevel >= FATAL)
! 			return true;
! 	}
! 	else if (elevel == TRACE)
! 	{
! 		/* log_min_level != LOG */
! 		if (log_min_level == TRACE || log_min_level <= ERROR)
! 			return true;
! 	}
! 	else if (log_min_level == TRACE)
! 	{
! 		/* elevel != TRACE, LOG or COMMERROR */
  		if (elevel >= FATAL)
  			return true;
  	}
*** ./src/backend/utils/misc/guc.c.orig	2008-07-09 11:14:31.000000000 +0100
--- ./src/backend/utils/misc/guc.c	2008-07-10 12:01:55.000000000 +0100
***************
*** 187,192 ****
--- 187,193 ----
  	{"log", LOG, false},
  	{"info", INFO, true},
  	{"notice", NOTICE, false},
+ 	{"trace", TRACE, false},
  	{"warning", WARNING, false},
  	{"error", ERROR, false},
  	{"fatal", FATAL, true},
***************
*** 205,210 ****
--- 206,212 ----
  	{"notice", NOTICE, false},
  	{"warning", WARNING, false},
  	{"error", ERROR, false},
+ 	{"trace", TRACE, false},
  	{"log", LOG, false},
  	{"fatal", FATAL, false},
  	{"panic", PANIC, false},
***************
*** 324,329 ****
--- 326,335 ----
  												 * above together */
  bool		log_btree_build_stats = false;
  
+ int			trace_min_planner_duration = -1;
+ int			trace_min_executor_duration = -1;
+ bool		trace_explain_plan = false;
+ 
  bool		check_function_bodies = true;
  bool		default_with_oids = false;
  bool		SQL_inheritance = true;
***************
*** 841,846 ****
--- 847,860 ----
  #endif
  
  	{
+ 		{"trace_explain_plan", PGC_USERSET, LOGGING_WHAT,
+ 			gettext_noop("Enables logging of execution plans for traced statements."),
+ 			NULL
+ 		},
+ 		&trace_explain_plan,
+ 		false, NULL, NULL
+ 	},
+ 	{
  		{"track_activities", PGC_SUSET, STATS_COLLECTOR,
  			gettext_noop("Collects information about executing commands."),
  			gettext_noop("Enables the collection of information on the currently "
***************
*** 1675,1680 ****
--- 1689,1716 ----
  	},
  
  	{
+ 		{"trace_min_planner_duration", PGC_USERSET, LOGGING_WHEN,
+ 			gettext_noop("Sets the minimum planner time above which "
+ 						 "statements will be traced."),
+ 			gettext_noop("Zero traces all queries. -1 turns this feature off."),
+ 			GUC_UNIT_MS
+ 		},
+ 		&trace_min_planner_duration,
+ 		-1, -1, INT_MAX / 1000, NULL, NULL
+ 	},
+ 
+ 	{
+ 		{"trace_min_executor_duration", PGC_USERSET, LOGGING_WHEN,
+ 			gettext_noop("Sets the minimum execution time above which "
+ 						 "statements will be traced."),
+ 			gettext_noop("Zero traces all queries. -1 turns this feature off."),
+ 			GUC_UNIT_MS
+ 		},
+ 		&trace_min_executor_duration,
+ 		-1, -1, INT_MAX / 1000, NULL, NULL
+ 	},
+ 
+ 	{
  		{"bgwriter_delay", PGC_SIGHUP, RESOURCES,
  			gettext_noop("Background writer sleep time between rounds."),
  			NULL,
*** ./src/include/commands/explain.h.orig	2008-07-08 13:56:55.000000000 +0100
--- ./src/include/commands/explain.h	2008-07-08 14:02:14.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/nodes/plannodes.h.orig	2008-07-09 11:34:51.000000000 +0100
--- ./src/include/nodes/plannodes.h	2008-07-10 12:00:02.000000000 +0100
***************
*** 35,40 ****
--- 35,42 ----
  {
  	NodeTag		type;
  
+ 	char		*query_string;	/* the orginal SQL query */
+ 
  	CmdType		commandType;	/* select|insert|update|delete */
  
  	bool		canSetTag;		/* do I set the command result tag? */
***************
*** 73,78 ****
--- 75,86 ----
  	List	   *relationOids;	/* OIDs of relations the plan depends on */
  
  	int			nParamExec;		/* number of PARAM_EXEC Params used */
+ 
+     /*
+ 	 * If tracing statements which are slow to plan, this records the
+ 	 * time taken by the planner (in seconds). Otherwise this will be 0.
+ 	 */
+ 	double		planner_time;
  } PlannedStmt;
  
  /* macro for fetching the Plan associated with a SubPlan node */
*** ./src/include/utils/elog.h.orig	2008-07-10 09:22:47.000000000 +0100
--- ./src/include/utils/elog.h	2008-07-10 09:26:21.000000000 +0100
***************
*** 34,53 ****
  #define NOTICE		18			/* Helpful messages to users about query
  								 * operation;  sent to client and server log
  								 * by default. */
! #define WARNING		19			/* Warnings.  NOTICE is for expected messages
  								 * like implicit sequence creation by SERIAL.
  								 * WARNING is for unexpected messages. */
! #define ERROR		20			/* user error - abort transaction; return to
  								 * known state */
  /* Save ERROR value in PGERROR so it can be restored when Win32 includes
   * modify it.  We have to use a constant rather than ERROR because macros
   * are expanded only when referenced outside macros.
   */
  #ifdef WIN32
! #define PGERROR		20
  #endif
! #define FATAL		21			/* fatal error - abort process */
! #define PANIC		22			/* take down the other backends with me */
  
   /* #define DEBUG DEBUG1 */	/* Backward compatibility with pre-7.3 */
  
--- 34,56 ----
  #define NOTICE		18			/* Helpful messages to users about query
  								 * operation;  sent to client and server log
  								 * by default. */
! #define TRACE		19			/* Trace message to users to help identify
! 								   slow running queries; sent only to the
! 								   client by default. */
! #define WARNING		20			/* Warnings.  NOTICE is for expected messages
  								 * like implicit sequence creation by SERIAL.
  								 * WARNING is for unexpected messages. */
! #define ERROR		21			/* user error - abort transaction; return to
  								 * known state */
  /* Save ERROR value in PGERROR so it can be restored when Win32 includes
   * modify it.  We have to use a constant rather than ERROR because macros
   * are expanded only when referenced outside macros.
   */
  #ifdef WIN32
! #define PGERROR		21
  #endif
! #define FATAL		22			/* fatal error - abort process */
! #define PANIC		23			/* take down the other backends with me */
  
   /* #define DEBUG DEBUG1 */	/* Backward compatibility with pre-7.3 */
  
*** ./src/include/utils/guc.h.orig	2008-07-08 14:07:20.000000000 +0100
--- ./src/include/utils/guc.h	2008-07-10 12:04:20.000000000 +0100
***************
*** 145,150 ****
--- 145,154 ----
  extern int	log_min_duration_statement;
  extern int	log_temp_files;
  
+ extern int	trace_min_planner_duration;
+ extern int	trace_min_executor_duration;
+ extern bool	trace_explain_plan;
+ 
  extern int	num_temp_buffers;
  
  extern char *ConfigFileName;

*** ./src/backend/commands/copy.c.orig	2008-07-09 16:14:54.000000000 +0100
--- ./src/backend/commands/copy.c	2008-07-09 16:15:54.000000000 +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.000000000 +0100
--- ./src/backend/commands/explain.c	2008-07-09 16:14:28.000000000 +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.000000000 +0100
--- ./src/backend/executor/execMain.c	2008-07-10 15:17:31.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 "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))
+ 		queryDesc->doInstrument = true;
+ 
+ 	/*
  	 * Copy other important information into the EState
  	 */
  	estate->es_snapshot = RegisterSnapshot(queryDesc->snapshot);
***************
*** 226,231 ****
--- 236,244 ----
  	bool		sendTuples;
  	TupleTableSlot *result;
  	MemoryContext oldcontext;
+ 	bool		time_planner = trace_min_planner_duration > -1;
+ 	bool		time_executor = trace_min_executor_duration > -1;
+ 	instr_time	starttime;
  
  	/* sanity checks */
  	Assert(queryDesc != NULL);
***************
*** 235,240 ****
--- 248,260 ----
  	Assert(estate != NULL);
  
  	/*
+ 	 * If tracing slow-running queries, record the start time before
+ 	 * running the query
+ 	 */
+ 	if (time_executor)
+ 		INSTR_TIME_SET_CURRENT(starttime);
+ 
+ 	/*
  	 * Switch into per-query memory context
  	 */
  	oldcontext = MemoryContextSwitchTo(estate->es_query_cxt);
***************
*** 278,283 ****
--- 298,378 ----
  
  	MemoryContextSwitchTo(oldcontext);
  
+ 	/*
+ 	 * If tracing slow queries, then we should log planner time,
+ 	 * execution time, statement SQL and execution time
+ 	 */
+ 	if (time_planner || time_executor)
+ 	{
+ 		bool log_stmt = false;
+ 		StringInfoData buf;
+ 		double planner_time_ms;
+ 		double executor_time_ms;
+ 
+ 		initStringInfo(&buf);
+ 
+ 		/* Log planner time if appropriate */
+ 		if (time_planner)
+ 		{
+ 			planner_time_ms = queryDesc->plannedstmt->planner_time * 1000.0;
+ 			if (planner_time_ms >= trace_min_planner_duration)
+ 			{
+ 				appendStringInfo(&buf, "planner time: %.3f ms  ",
+ 								 planner_time_ms);
+ 				log_stmt = true;
+ 			}
+ 			/* Don't log again, unless re-planned and still slow */
+ 			queryDesc->plannedstmt->planner_time = 0.0;
+ 		}
+ 
+ 		/* Log execution time if appropriate */
+ 		if (time_executor)
+ 		{
+ 			executor_time_ms = elapsed_time(&starttime) * 1000.0;
+ 			if (executor_time_ms >= trace_min_executor_duration)
+ 			{
+ 				appendStringInfo(&buf, "executor time: %.3f ms  ",
+ 								 executor_time_ms);
+ 				log_stmt = true;
+ 			}
+ 		}
+ 
+ 		/*
+ 		 * Only if either of the above caused the statement to be logged,
+ 		 * then log the statement SQL and maybe its execution plan
+ 		 */
+ 		if (log_stmt)
+ 		{
+ 			if (queryDesc->plannedstmt->query_string)
+ 				appendStringInfo(&buf, "statement: %s",
+ 								 queryDesc->plannedstmt->query_string);
+ 
+ 			if (trace_explain_plan)
+ 			{
+ 				ExplainState *es;
+ 
+ 				es = (ExplainState *) palloc0(sizeof(ExplainState));
+ 
+ 				es->printTList = false;
+ 				es->printAnalyze = true;
+ 				es->pstmt = queryDesc->plannedstmt;
+ 				es->rtable = queryDesc->plannedstmt->rtable;
+ 
+ 				appendStringInfo(&buf, "  plan:\n");
+ 				explain_outNode(&buf,
+ 								queryDesc->plannedstmt->planTree,
+ 								queryDesc->planstate,
+ 								NULL, 0, es);
+ 				pfree(es);
+ 			}
+ 
+ 			/* Finally log this trace report */
+ 			ereport(TRACE, (errmsg(buf.data)));
+ 		}
+ 
+ 		pfree(buf.data);
+ 	}
+ 
  	return result;
  }
  
*** ./src/backend/executor/spi.c.orig	2008-07-09 15:52:10.000000000 +0100
--- ./src/backend/executor/spi.c	2008-07-09 15:58:20.000000000 +0100
***************
*** 1764,1769 ****
--- 1764,1770 ----
  				else
  					snap = InvalidSnapshot;
  
+ 				((PlannedStmt *)stmt)->query_string = plansource->query_string;
  				qdesc = CreateQueryDesc((PlannedStmt *) stmt,
  										snap, crosscheck_snapshot,
  										dest,
*** ./src/backend/optimizer/plan/planner.c.orig	2008-07-09 11:38:06.000000000 +0100
--- ./src/backend/optimizer/plan/planner.c	2008-07-10 15:17:19.000000000 +0100
***************
*** 18,24 ****
--- 18,26 ----
  #include <limits.h>
  
  #include "catalog/pg_operator.h"
+ #include "commands/explain.h"
  #include "executor/executor.h"
+ #include "executor/instrument.h"
  #include "executor/nodeAgg.h"
  #include "miscadmin.h"
  #include "nodes/makefuncs.h"
***************
*** 38,43 ****
--- 40,46 ----
  #include "parser/parse_expr.h"
  #include "parser/parse_oper.h"
  #include "parser/parsetree.h"
+ #include "utils/guc.h"
  #include "utils/lsyscache.h"
  #include "utils/syscache.h"
  
***************
*** 99,109 ****
--- 102,128 ----
  planner(Query *parse, int cursorOptions, ParamListInfo boundParams)
  {
  	PlannedStmt *result;
+ 	instr_time starttime;
  
+ 	/*
+ 	 * If we are tracing statements which take a long time to plan,
+ 	 * then time how long this takes.
+ 	 */
+ 	if (trace_min_planner_duration > -1)
+ 		INSTR_TIME_SET_CURRENT(starttime);
+ 
+ 	/* Plan the query */
  	if (planner_hook)
  		result = (*planner_hook) (parse, cursorOptions, boundParams);
  	else
  		result = standard_planner(parse, cursorOptions, boundParams);
+ 
+ 	/* Record how long it took, if appropriate */
+ 	if (trace_min_planner_duration > -1)
+ 		result->planner_time = elapsed_time(&starttime);
+ 	else
+ 		result->planner_time = 0.0;
+ 
  	return result;
  }
  
*** ./src/backend/tcop/pquery.c.orig	2008-07-09 16:58:07.000000000 +0100
--- ./src/backend/tcop/pquery.c	2008-07-10 10:33:52.000000000 +0100
***************
*** 895,900 ****
--- 895,903 ----
  	 */
  	queryDesc = PortalGetQueryDesc(portal);
  
+ 	if (queryDesc)
+ 		queryDesc->plannedstmt->query_string = portal->sourceText;
+ 
  	/* Caller messed up if we have neither a ready query nor held data. */
  	Assert(queryDesc || portal->holdStore);
  
***************
*** 1236,1241 ****
--- 1239,1245 ----
  			 * process a plannable query.
  			 */
  			PlannedStmt *pstmt = (PlannedStmt *) stmt;
+ 			pstmt->query_string = portal->sourceText;
  
  			if (log_executor_stats)
  				ResetUsage();
*** ./src/backend/utils/error/elog.c.orig	2008-07-10 09:27:12.000000000 +0100
--- ./src/backend/utils/error/elog.c	2008-07-10 10:09:11.000000000 +0100
***************
*** 1428,1433 ****
--- 1428,1434 ----
  		case COMMERROR:
  		case INFO:
  		case NOTICE:
+ 		case TRACE:
  			eventlevel = EVENTLOG_INFORMATION_TYPE;
  			break;
  		case WARNING:
***************
*** 2027,2032 ****
--- 2028,2034 ----
  				syslog_level = LOG_INFO;
  				break;
  			case NOTICE:
+ 			case TRACE:
  			case WARNING:
  				syslog_level = LOG_NOTICE;
  				break;
***************
*** 2416,2421 ****
--- 2418,2426 ----
  		case NOTICE:
  			prefix = _("NOTICE");
  			break;
+ 		case TRACE:
+ 			prefix = _("TRACE");
+ 			break;
  		case WARNING:
  			prefix = _("WARNING");
  			break;
***************
*** 2506,2511 ****
--- 2511,2519 ----
   * between ERROR and FATAL.  Generally this is the right thing for testing
   * whether a message should go to the postmaster log, whereas a simple >=
   * test is correct for testing whether the message should go to the client.
+  *
+  * Similarly, TRACE is considered to be between ERROR and LOG (<FATAL)
+  * for the purposes of the postmaster log, and so is not output by default.
   */
  static bool
  is_log_level_output(int elevel, int log_min_level)
***************
*** 2517,2523 ****
  	}
  	else if (log_min_level == LOG)
  	{
! 		/* elevel != LOG */
  		if (elevel >= FATAL)
  			return true;
  	}
--- 2525,2543 ----
  	}
  	else if (log_min_level == LOG)
  	{
! 		/* elevel != LOG or COMMERROR */
! 		if (elevel >= FATAL)
! 			return true;
! 	}
! 	else if (elevel == TRACE)
! 	{
! 		/* log_min_level != LOG */
! 		if (log_min_level == TRACE || log_min_level <= ERROR)
! 			return true;
! 	}
! 	else if (log_min_level == TRACE)
! 	{
! 		/* elevel != TRACE, LOG or COMMERROR */
  		if (elevel >= FATAL)
  			return true;
  	}
*** ./src/backend/utils/misc/guc.c.orig	2008-07-09 11:14:31.000000000 +0100
--- ./src/backend/utils/misc/guc.c	2008-07-10 12:01:55.000000000 +0100
***************
*** 187,192 ****
--- 187,193 ----
  	{"log", LOG, false},
  	{"info", INFO, true},
  	{"notice", NOTICE, false},
+ 	{"trace", TRACE, false},
  	{"warning", WARNING, false},
  	{"error", ERROR, false},
  	{"fatal", FATAL, true},
***************
*** 205,210 ****
--- 206,212 ----
  	{"notice", NOTICE, false},
  	{"warning", WARNING, false},
  	{"error", ERROR, false},
+ 	{"trace", TRACE, false},
  	{"log", LOG, false},
  	{"fatal", FATAL, false},
  	{"panic", PANIC, false},
***************
*** 324,329 ****
--- 326,335 ----
  												 * above together */
  bool		log_btree_build_stats = false;
  
+ int			trace_min_planner_duration = -1;
+ int			trace_min_executor_duration = -1;
+ bool		trace_explain_plan = false;
+ 
  bool		check_function_bodies = true;
  bool		default_with_oids = false;
  bool		SQL_inheritance = true;
***************
*** 841,846 ****
--- 847,860 ----
  #endif
  
  	{
+ 		{"trace_explain_plan", PGC_USERSET, LOGGING_WHAT,
+ 			gettext_noop("Enables logging of execution plans for traced statements."),
+ 			NULL
+ 		},
+ 		&trace_explain_plan,
+ 		false, NULL, NULL
+ 	},
+ 	{
  		{"track_activities", PGC_SUSET, STATS_COLLECTOR,
  			gettext_noop("Collects information about executing commands."),
  			gettext_noop("Enables the collection of information on the currently "
***************
*** 1675,1680 ****
--- 1689,1716 ----
  	},
  
  	{
+ 		{"trace_min_planner_duration", PGC_USERSET, LOGGING_WHEN,
+ 			gettext_noop("Sets the minimum planner time above which "
+ 						 "statements will be traced."),
+ 			gettext_noop("Zero traces all queries. -1 turns this feature off."),
+ 			GUC_UNIT_MS
+ 		},
+ 		&trace_min_planner_duration,
+ 		-1, -1, INT_MAX / 1000, NULL, NULL
+ 	},
+ 
+ 	{
+ 		{"trace_min_executor_duration", PGC_USERSET, LOGGING_WHEN,
+ 			gettext_noop("Sets the minimum execution time above which "
+ 						 "statements will be traced."),
+ 			gettext_noop("Zero traces all queries. -1 turns this feature off."),
+ 			GUC_UNIT_MS
+ 		},
+ 		&trace_min_executor_duration,
+ 		-1, -1, INT_MAX / 1000, NULL, NULL
+ 	},
+ 
+ 	{
  		{"bgwriter_delay", PGC_SIGHUP, RESOURCES,
  			gettext_noop("Background writer sleep time between rounds."),
  			NULL,
*** ./src/bin/psql/common.c.orig	2008-07-10 15:05:14.000000000 +0100
--- ./src/bin/psql/common.c	2008-07-10 15:05:51.000000000 +0100
***************
*** 26,32 ****
  #include "copy.h"
  #include "mbprint.h"
  
! 
  
  static bool ExecQueryUsingCursor(const char *query, double *elapsed_msec);
  static bool command_no_begin(const char *query);
--- 26,33 ----
  #include "copy.h"
  #include "mbprint.h"
  
! /* Flag to ignore backend notices (used during tab-completion) */
! bool ignore_notices = false;
  
  static bool ExecQueryUsingCursor(const char *query, double *elapsed_msec);
  static bool command_no_begin(const char *query);
***************
*** 180,186 ****
  NoticeProcessor(void *arg, const char *message)
  {
  	(void) arg;					/* not used */
! 	psql_error("%s", message);
  }
  
  
--- 181,189 ----
  NoticeProcessor(void *arg, const char *message)
  {
  	(void) arg;					/* not used */
! 
! 	if (!ignore_notices)
! 		psql_error("%s", message);
  }
  
  
*** ./src/bin/psql/common.h.orig	2008-07-10 15:03:38.000000000 +0100
--- ./src/bin/psql/common.h	2008-07-10 15:04:37.000000000 +0100
***************
*** 63,66 ****
--- 63,69 ----
  
  extern char *expand_tilde(char **filename);
  
+ /* Flag to ignore backend notices (used during tab-completion) */
+ extern bool ignore_notices;
+ 
  #endif   /* COMMON_H */
*** ./src/bin/psql/tab-complete.c.orig	2008-07-10 15:06:22.000000000 +0100
--- ./src/bin/psql/tab-complete.c	2008-07-10 15:06:57.000000000 +0100
***************
*** 2575,2581 ****
--- 2575,2583 ----
  	if (query == NULL || !pset.db || PQstatus(pset.db) != CONNECTION_OK)
  		return NULL;
  
+ 	ignore_notices = true;
  	result = PQexec(pset.db, query);
+ 	ignore_notices = false;
  
  	if (result != NULL && PQresultStatus(result) != PGRES_TUPLES_OK)
  	{
*** ./src/include/commands/explain.h.orig	2008-07-08 13:56:55.000000000 +0100
--- ./src/include/commands/explain.h	2008-07-08 14:02:14.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/nodes/plannodes.h.orig	2008-07-09 11:34:51.000000000 +0100
--- ./src/include/nodes/plannodes.h	2008-07-10 12:00:02.000000000 +0100
***************
*** 35,40 ****
--- 35,42 ----
  {
  	NodeTag		type;
  
+ 	char		*query_string;	/* the orginal SQL query */
+ 
  	CmdType		commandType;	/* select|insert|update|delete */
  
  	bool		canSetTag;		/* do I set the command result tag? */
***************
*** 73,78 ****
--- 75,86 ----
  	List	   *relationOids;	/* OIDs of relations the plan depends on */
  
  	int			nParamExec;		/* number of PARAM_EXEC Params used */
+ 
+     /*
+ 	 * If tracing statements which are slow to plan, this records the
+ 	 * time taken by the planner (in seconds). Otherwise this will be 0.
+ 	 */
+ 	double		planner_time;
  } PlannedStmt;
  
  /* macro for fetching the Plan associated with a SubPlan node */
*** ./src/include/utils/elog.h.orig	2008-07-10 09:22:47.000000000 +0100
--- ./src/include/utils/elog.h	2008-07-10 09:26:21.000000000 +0100
***************
*** 34,53 ****
  #define NOTICE		18			/* Helpful messages to users about query
  								 * operation;  sent to client and server log
  								 * by default. */
! #define WARNING		19			/* Warnings.  NOTICE is for expected messages
  								 * like implicit sequence creation by SERIAL.
  								 * WARNING is for unexpected messages. */
! #define ERROR		20			/* user error - abort transaction; return to
  								 * known state */
  /* Save ERROR value in PGERROR so it can be restored when Win32 includes
   * modify it.  We have to use a constant rather than ERROR because macros
   * are expanded only when referenced outside macros.
   */
  #ifdef WIN32
! #define PGERROR		20
  #endif
! #define FATAL		21			/* fatal error - abort process */
! #define PANIC		22			/* take down the other backends with me */
  
   /* #define DEBUG DEBUG1 */	/* Backward compatibility with pre-7.3 */
  
--- 34,56 ----
  #define NOTICE		18			/* Helpful messages to users about query
  								 * operation;  sent to client and server log
  								 * by default. */
! #define TRACE		19			/* Trace message to users to help identify
! 								   slow running queries; sent only to the
! 								   client by default. */
! #define WARNING		20			/* Warnings.  NOTICE is for expected messages
  								 * like implicit sequence creation by SERIAL.
  								 * WARNING is for unexpected messages. */
! #define ERROR		21			/* user error - abort transaction; return to
  								 * known state */
  /* Save ERROR value in PGERROR so it can be restored when Win32 includes
   * modify it.  We have to use a constant rather than ERROR because macros
   * are expanded only when referenced outside macros.
   */
  #ifdef WIN32
! #define PGERROR		21
  #endif
! #define FATAL		22			/* fatal error - abort process */
! #define PANIC		23			/* take down the other backends with me */
  
   /* #define DEBUG DEBUG1 */	/* Backward compatibility with pre-7.3 */
  
*** ./src/include/utils/guc.h.orig	2008-07-08 14:07:20.000000000 +0100
--- ./src/include/utils/guc.h	2008-07-10 12:04:20.000000000 +0100
***************
*** 145,150 ****
--- 145,154 ----
  extern int	log_min_duration_statement;
  extern int	log_temp_files;
  
+ extern int	trace_min_planner_duration;
+ extern int	trace_min_executor_duration;
+ extern bool	trace_explain_plan;
+ 
  extern int	num_temp_buffers;
  
  extern char *ConfigFileName;

Index: src/backend/commands/explain.c
===================================================================
--- src/backend/commands/explain.c	(8.4dev 2008-08-26)
+++ src/backend/commands/explain.c	(working copy)
@@ -224,7 +224,6 @@
 	QueryDesc  *queryDesc;
 	instr_time	starttime;
 	double		totaltime = 0;
-	ExplainState *es;
 	StringInfoData buf;
 	int			eflags;
 
@@ -265,17 +264,8 @@
 		totaltime += elapsed_time(&starttime);
 	}
 
-	es = (ExplainState *) palloc0(sizeof(ExplainState));
-
-	es->printTList = stmt->verbose;
-	es->printAnalyze = stmt->analyze;
-	es->pstmt = queryDesc->plannedstmt;
-	es->rtable = queryDesc->plannedstmt->rtable;
-
 	initStringInfo(&buf);
-	explain_outNode(&buf,
-					queryDesc->plannedstmt->planTree, queryDesc->planstate,
-					NULL, 0, es);
+	ExplainOneResult(&buf, queryDesc, stmt->analyze, stmt->verbose);
 
 	/*
 	 * If we ran the command, run any AFTER triggers it queued.  (Note this
@@ -290,7 +280,7 @@
 	}
 
 	/* Print info about runtime of triggers */
-	if (es->printAnalyze)
+	if (stmt->analyze)
 	{
 		ResultRelInfo *rInfo;
 		bool		show_relname;
@@ -335,10 +325,29 @@
 	do_text_output_multiline(tstate, buf.data);
 
 	pfree(buf.data);
-	pfree(es);
 }
 
 /*
+ * ExplainOneResult -
+ *	  converts a Plan node into ascii string and appends it to 'str'
+ */
+void
+ExplainOneResult(StringInfo str, QueryDesc *queryDesc,
+				 bool analyze, bool verbose)
+{
+	ExplainState	es = { 0 };
+
+	es.printTList = verbose;
+	es.printAnalyze = analyze;
+	es.pstmt = queryDesc->plannedstmt;
+	es.rtable = queryDesc->plannedstmt->rtable;
+
+	explain_outNode(str,
+					queryDesc->plannedstmt->planTree, queryDesc->planstate,
+					NULL, 0, &es);
+}
+
+/*
  * report_triggers -
  *		report execution stats for a single relation's triggers
  */
Index: src/include/commands/explain.h
===================================================================
--- src/include/commands/explain.h	(8.4dev 2008-08-26)
+++ src/include/commands/explain.h	(working copy)
@@ -41,4 +41,7 @@
 extern void ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
 			   ExplainStmt *stmt, TupOutputState *tstate);
 
+extern void ExplainOneResult(StringInfo str, QueryDesc *queryDesc,
+							 bool analyze, bool verbose);
+
 #endif   /* EXPLAIN_H */

Index: src/backend/utils/misc/guc.c
===================================================================
--- src/backend/utils/misc/guc.c	(8.4dev 2008-08-28)
+++ src/backend/utils/misc/guc.c	(working copy)
@@ -5588,6 +5588,7 @@
 init_custom_variable(const char *name,
 					 const char *short_desc,
 					 const char *long_desc,
+					 int flags,
 					 GucContext context,
 					 enum config_type type,
 					 size_t sz)
@@ -5602,6 +5603,7 @@
 	gen->group = CUSTOM_OPTIONS;
 	gen->short_desc = short_desc;
 	gen->long_desc = long_desc;
+	gen->flags = flags;
 	gen->vartype = type;
 
 	return gen;
@@ -5677,6 +5679,7 @@
 DefineCustomBoolVariable(const char *name,
 						 const char *short_desc,
 						 const char *long_desc,
+						 int flags,
 						 bool *valueAddr,
 						 GucContext context,
 						 GucBoolAssignHook assign_hook,
@@ -5685,7 +5688,7 @@
 	struct config_bool *var;
 
 	var = (struct config_bool *)
-		init_custom_variable(name, short_desc, long_desc, context,
+		init_custom_variable(name, short_desc, long_desc, flags, context,
 							 PGC_BOOL, sizeof(struct config_bool));
 	var->variable = valueAddr;
 	var->boot_val = *valueAddr;
@@ -5699,6 +5702,7 @@
 DefineCustomIntVariable(const char *name,
 						const char *short_desc,
 						const char *long_desc,
+						int flags,
 						int *valueAddr,
 						int minValue,
 						int maxValue,
@@ -5709,7 +5713,7 @@
 	struct config_int *var;
 
 	var = (struct config_int *)
-		init_custom_variable(name, short_desc, long_desc, context,
+		init_custom_variable(name, short_desc, long_desc, flags, context,
 							 PGC_INT, sizeof(struct config_int));
 	var->variable = valueAddr;
 	var->boot_val = *valueAddr;
@@ -5725,6 +5729,7 @@
 DefineCustomRealVariable(const char *name,
 						 const char *short_desc,
 						 const char *long_desc,
+						 int flags,
 						 double *valueAddr,
 						 double minValue,
 						 double maxValue,
@@ -5735,7 +5740,7 @@
 	struct config_real *var;
 
 	var = (struct config_real *)
-		init_custom_variable(name, short_desc, long_desc, context,
+		init_custom_variable(name, short_desc, long_desc, flags, context,
 							 PGC_REAL, sizeof(struct config_real));
 	var->variable = valueAddr;
 	var->boot_val = *valueAddr;
@@ -5751,6 +5756,7 @@
 DefineCustomStringVariable(const char *name,
 						   const char *short_desc,
 						   const char *long_desc,
+						   int flags,
 						   char **valueAddr,
 						   GucContext context,
 						   GucStringAssignHook assign_hook,
@@ -5759,7 +5765,7 @@
 	struct config_string *var;
 
 	var = (struct config_string *)
-		init_custom_variable(name, short_desc, long_desc, context,
+		init_custom_variable(name, short_desc, long_desc, flags, context,
 							 PGC_STRING, sizeof(struct config_string));
 	var->variable = valueAddr;
 	var->boot_val = *valueAddr;
@@ -5775,6 +5781,7 @@
 DefineCustomEnumVariable(const char *name,
 						 const char *short_desc,
 						 const char *long_desc,
+						 int flags,
 						 int *valueAddr,
 						 const struct config_enum_entry *options,
 						 GucContext context,
@@ -5784,7 +5791,7 @@
 	struct config_enum *var;
 
 	var = (struct config_enum *)
-		init_custom_variable(name, short_desc, long_desc, context,
+		init_custom_variable(name, short_desc, long_desc, flags, context,
 							 PGC_ENUM, sizeof(struct config_enum));
 	var->variable = valueAddr;
 	var->boot_val = *valueAddr;
Index: src/include/utils/guc.h
===================================================================
--- src/include/utils/guc.h	(8.4dev 2008-08-28)
+++ src/include/utils/guc.h	(working copy)
@@ -163,6 +163,7 @@
 						 const char *name,
 						 const char *short_desc,
 						 const char *long_desc,
+						 int flags,
 						 bool *valueAddr,
 						 GucContext context,
 						 GucBoolAssignHook assign_hook,
@@ -172,6 +173,7 @@
 						const char *name,
 						const char *short_desc,
 						const char *long_desc,
+						int flags,
 						int *valueAddr,
 						int minValue,
 						int maxValue,
@@ -183,6 +185,7 @@
 						 const char *name,
 						 const char *short_desc,
 						 const char *long_desc,
+						 int flags,
 						 double *valueAddr,
 						 double minValue,
 						 double maxValue,
@@ -194,6 +197,7 @@
 						   const char *name,
 						   const char *short_desc,
 						   const char *long_desc,
+						   int flags,
 						   char **valueAddr,
 						   GucContext context,
 						   GucStringAssignHook assign_hook,
@@ -203,6 +207,7 @@
 						   const char *name,
 						   const char *short_desc,
 						   const char *long_desc,
+						   int flags,
 						   int *valueAddr,
 						   const struct config_enum_entry *options,
 						   GucContext context,

Index: src/backend/commands/explain.c
===================================================================
--- src/backend/commands/explain.c	(8.4dev 2008-08-26)
+++ src/backend/commands/explain.c	(working copy)
@@ -224,7 +224,6 @@
 	QueryDesc  *queryDesc;
 	instr_time	starttime;
 	double		totaltime = 0;
-	ExplainState *es;
 	StringInfoData buf;
 	int			eflags;
 
@@ -265,17 +264,8 @@
 		totaltime += elapsed_time(&starttime);
 	}
 
-	es = (ExplainState *) palloc0(sizeof(ExplainState));
-
-	es->printTList = stmt->verbose;
-	es->printAnalyze = stmt->analyze;
-	es->pstmt = queryDesc->plannedstmt;
-	es->rtable = queryDesc->plannedstmt->rtable;
-
 	initStringInfo(&buf);
-	explain_outNode(&buf,
-					queryDesc->plannedstmt->planTree, queryDesc->planstate,
-					NULL, 0, es);
+	ExplainOneResult(&buf, queryDesc, stmt->analyze, stmt->verbose);
 
 	/*
 	 * If we ran the command, run any AFTER triggers it queued.  (Note this
@@ -290,7 +280,7 @@
 	}
 
 	/* Print info about runtime of triggers */
-	if (es->printAnalyze)
+	if (stmt->analyze)
 	{
 		ResultRelInfo *rInfo;
 		bool		show_relname;
@@ -335,10 +325,29 @@
 	do_text_output_multiline(tstate, buf.data);
 
 	pfree(buf.data);
-	pfree(es);
 }
 
 /*
+ * ExplainOneResult -
+ *	  converts a Plan node into ascii string and appends it to 'str'
+ */
+void
+ExplainOneResult(StringInfo str, QueryDesc *queryDesc,
+				 bool analyze, bool verbose)
+{
+	ExplainState	es = { 0 };
+
+	es.printTList = verbose;
+	es.printAnalyze = analyze;
+	es.pstmt = queryDesc->plannedstmt;
+	es.rtable = queryDesc->plannedstmt->rtable;
+
+	explain_outNode(str,
+					queryDesc->plannedstmt->planTree, queryDesc->planstate,
+					NULL, 0, &es);
+}
+
+/*
  * report_triggers -
  *		report execution stats for a single relation's triggers
  */
Index: src/include/commands/explain.h
===================================================================
--- src/include/commands/explain.h	(8.4dev 2008-08-26)
+++ src/include/commands/explain.h	(working copy)
@@ -41,4 +41,7 @@
 extern void ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
 			   ExplainStmt *stmt, TupOutputState *tstate);
 
+extern void ExplainOneResult(StringInfo str, QueryDesc *queryDesc,
+							 bool analyze, bool verbose);
+
 #endif   /* EXPLAIN_H */

Index: src/bin/psql/command.c
===================================================================
--- src/bin/psql/command.c	(8.4dev 2008-08-28)
+++ src/bin/psql/command.c	(working copy)
@@ -333,6 +333,7 @@
 
 		show_verbose = strchr(cmd, '+') ? true : false;
 
+		ignore_notices = true;
 		switch (cmd[1])
 		{
 			case '\0':
@@ -418,6 +419,7 @@
 			default:
 				status = PSQL_CMD_UNKNOWN;
 		}
+		ignore_notices = false;
 
 		if (pattern)
 			free(pattern);
Index: src/bin/psql/common.c
===================================================================
--- src/bin/psql/common.c	(8.4dev 2008-08-28)
+++ src/bin/psql/common.c	(working copy)
@@ -26,8 +26,9 @@
 #include "copy.h"
 #include "mbprint.h"
 
+/* Flag to ignore backend notices (used during tab-completion) */
+bool ignore_notices = false;
 
-
 static bool ExecQueryUsingCursor(const char *query, double *elapsed_msec);
 static bool command_no_begin(const char *query);
 static bool is_select_command(const char *query);
@@ -180,7 +181,9 @@
 NoticeProcessor(void *arg, const char *message)
 {
 	(void) arg;					/* not used */
-	psql_error("%s", message);
+
+	if (!ignore_notices)
+		psql_error("%s", message);
 }
 
 
Index: src/bin/psql/common.h
===================================================================
--- src/bin/psql/common.h	(8.4dev 2008-08-28)
+++ src/bin/psql/common.h	(working copy)
@@ -63,4 +63,7 @@
 
 extern char *expand_tilde(char **filename);
 
+/* Flag to ignore backend notices (used during tab-completion) */
+extern bool ignore_notices;
+
 #endif   /* COMMON_H */
Index: src/bin/psql/tab-complete.c
===================================================================
--- src/bin/psql/tab-complete.c	(8.4dev 2008-08-28)
+++ src/bin/psql/tab-complete.c	(working copy)
@@ -2575,7 +2575,9 @@
 	if (query == NULL || !pset.db || PQstatus(pset.db) != CONNECTION_OK)
 		return NULL;
 
+	ignore_notices = true;
 	result = PQexec(pset.db, query);
+	ignore_notices = false;
 
 	if (PQresultStatus(result) != PGRES_TUPLES_OK)
 	{

*** a/src/backend/utils/misc/guc.c
--- b/src/backend/utils/misc/guc.c
***************
*** 5619,5624 **** static struct config_generic *
--- 5619,5625 ----
  init_custom_variable(const char *name,
  					 const char *short_desc,
  					 const char *long_desc,
+ 					 int flags,
  					 GucContext context,
  					 enum config_type type,
  					 size_t sz)
***************
*** 5633,5638 **** init_custom_variable(const char *name,
--- 5634,5640 ----
  	gen->group = CUSTOM_OPTIONS;
  	gen->short_desc = short_desc;
  	gen->long_desc = long_desc;
+ 	gen->flags = flags;
  	gen->vartype = type;
  
  	return gen;
***************
*** 5708,5713 **** void
--- 5710,5716 ----
  DefineCustomBoolVariable(const char *name,
  						 const char *short_desc,
  						 const char *long_desc,
+ 						 int flags,
  						 bool *valueAddr,
  						 GucContext context,
  						 GucBoolAssignHook assign_hook,
***************
*** 5716,5722 **** DefineCustomBoolVariable(const char *name,
  	struct config_bool *var;
  
  	var = (struct config_bool *)
! 		init_custom_variable(name, short_desc, long_desc, context,
  							 PGC_BOOL, sizeof(struct config_bool));
  	var->variable = valueAddr;
  	var->boot_val = *valueAddr;
--- 5719,5725 ----
  	struct config_bool *var;
  
  	var = (struct config_bool *)
! 		init_custom_variable(name, short_desc, long_desc, flags, context,
  							 PGC_BOOL, sizeof(struct config_bool));
  	var->variable = valueAddr;
  	var->boot_val = *valueAddr;
***************
*** 5730,5735 **** void
--- 5733,5739 ----
  DefineCustomIntVariable(const char *name,
  						const char *short_desc,
  						const char *long_desc,
+ 						int flags,
  						int *valueAddr,
  						int minValue,
  						int maxValue,
***************
*** 5740,5746 **** DefineCustomIntVariable(const char *name,
  	struct config_int *var;
  
  	var = (struct config_int *)
! 		init_custom_variable(name, short_desc, long_desc, context,
  							 PGC_INT, sizeof(struct config_int));
  	var->variable = valueAddr;
  	var->boot_val = *valueAddr;
--- 5744,5750 ----
  	struct config_int *var;
  
  	var = (struct config_int *)
! 		init_custom_variable(name, short_desc, long_desc, flags, context,
  							 PGC_INT, sizeof(struct config_int));
  	var->variable = valueAddr;
  	var->boot_val = *valueAddr;
***************
*** 5756,5761 **** void
--- 5760,5766 ----
  DefineCustomRealVariable(const char *name,
  						 const char *short_desc,
  						 const char *long_desc,
+ 						 int flags,
  						 double *valueAddr,
  						 double minValue,
  						 double maxValue,
***************
*** 5766,5772 **** DefineCustomRealVariable(const char *name,
  	struct config_real *var;
  
  	var = (struct config_real *)
! 		init_custom_variable(name, short_desc, long_desc, context,
  							 PGC_REAL, sizeof(struct config_real));
  	var->variable = valueAddr;
  	var->boot_val = *valueAddr;
--- 5771,5777 ----
  	struct config_real *var;
  
  	var = (struct config_real *)
! 		init_custom_variable(name, short_desc, long_desc, flags, context,
  							 PGC_REAL, sizeof(struct config_real));
  	var->variable = valueAddr;
  	var->boot_val = *valueAddr;
***************
*** 5782,5787 **** void
--- 5787,5793 ----
  DefineCustomStringVariable(const char *name,
  						   const char *short_desc,
  						   const char *long_desc,
+ 						   int flags,
  						   char **valueAddr,
  						   GucContext context,
  						   GucStringAssignHook assign_hook,
***************
*** 5790,5796 **** DefineCustomStringVariable(const char *name,
  	struct config_string *var;
  
  	var = (struct config_string *)
! 		init_custom_variable(name, short_desc, long_desc, context,
  							 PGC_STRING, sizeof(struct config_string));
  	var->variable = valueAddr;
  	var->boot_val = *valueAddr;
--- 5796,5802 ----
  	struct config_string *var;
  
  	var = (struct config_string *)
! 		init_custom_variable(name, short_desc, long_desc, flags, context,
  							 PGC_STRING, sizeof(struct config_string));
  	var->variable = valueAddr;
  	var->boot_val = *valueAddr;
***************
*** 5806,5811 **** void
--- 5812,5818 ----
  DefineCustomEnumVariable(const char *name,
  						 const char *short_desc,
  						 const char *long_desc,
+ 						 int flags,
  						 int *valueAddr,
  						 const struct config_enum_entry *options,
  						 GucContext context,
***************
*** 5815,5821 **** DefineCustomEnumVariable(const char *name,
  	struct config_enum *var;
  
  	var = (struct config_enum *)
! 		init_custom_variable(name, short_desc, long_desc, context,
  							 PGC_ENUM, sizeof(struct config_enum));
  	var->variable = valueAddr;
  	var->boot_val = *valueAddr;
--- 5822,5828 ----
  	struct config_enum *var;
  
  	var = (struct config_enum *)
! 		init_custom_variable(name, short_desc, long_desc, flags, context,
  							 PGC_ENUM, sizeof(struct config_enum));
  	var->variable = valueAddr;
  	var->boot_val = *valueAddr;
*** a/src/include/utils/guc.h
--- b/src/include/utils/guc.h
***************
*** 163,168 **** extern void DefineCustomBoolVariable(
--- 163,169 ----
  						 const char *name,
  						 const char *short_desc,
  						 const char *long_desc,
+ 						 int flags,
  						 bool *valueAddr,
  						 GucContext context,
  						 GucBoolAssignHook assign_hook,
***************
*** 172,177 **** extern void DefineCustomIntVariable(
--- 173,179 ----
  						const char *name,
  						const char *short_desc,
  						const char *long_desc,
+ 						int flags,
  						int *valueAddr,
  						int minValue,
  						int maxValue,
***************
*** 183,188 **** extern void DefineCustomRealVariable(
--- 185,191 ----
  						 const char *name,
  						 const char *short_desc,
  						 const char *long_desc,
+ 						 int flags,
  						 double *valueAddr,
  						 double minValue,
  						 double maxValue,
***************
*** 194,199 **** extern void DefineCustomStringVariable(
--- 197,203 ----
  						   const char *name,
  						   const char *short_desc,
  						   const char *long_desc,
+ 						   int flags,
  						   char **valueAddr,
  						   GucContext context,
  						   GucStringAssignHook assign_hook,
***************
*** 203,208 **** extern void DefineCustomEnumVariable(
--- 207,213 ----
  						   const char *name,
  						   const char *short_desc,
  						   const char *long_desc,
+ 						   int flags,
  						   int *valueAddr,
  						   const struct config_enum_entry *options,
  						   GucContext context,

diff -cpr HEAD/src/backend/commands/explain.c auto_explain/src/backend/commands/explain.c
*** HEAD/src/backend/commands/explain.c	Tue Oct  7 05:29:38 2008
--- auto_explain/src/backend/commands/explain.c	Thu Oct  9 18:10:23 2008
*************** ExplainOnePlan(PlannedStmt *plannedstmt,
*** 224,230 ****
  	QueryDesc  *queryDesc;
  	instr_time	starttime;
  	double		totaltime = 0;
- 	ExplainState *es;
  	StringInfoData buf;
  	int			eflags;
  
--- 224,229 ----
*************** ExplainOnePlan(PlannedStmt *plannedstmt,
*** 265,281 ****
  		totaltime += elapsed_time(&starttime);
  	}
  
- 	es = (ExplainState *) palloc0(sizeof(ExplainState));
- 
- 	es->printTList = stmt->verbose;
- 	es->printAnalyze = stmt->analyze;
- 	es->pstmt = queryDesc->plannedstmt;
- 	es->rtable = queryDesc->plannedstmt->rtable;
- 
  	initStringInfo(&buf);
! 	explain_outNode(&buf,
! 					queryDesc->plannedstmt->planTree, queryDesc->planstate,
! 					NULL, 0, es);
  
  	/*
  	 * If we ran the command, run any AFTER triggers it queued.  (Note this
--- 264,271 ----
  		totaltime += elapsed_time(&starttime);
  	}
  
  	initStringInfo(&buf);
! 	ExplainOneResult(&buf, queryDesc, stmt->analyze, stmt->verbose);
  
  	/*
  	 * If we ran the command, run any AFTER triggers it queued.  (Note this
*************** ExplainOnePlan(PlannedStmt *plannedstmt,
*** 290,296 ****
  	}
  
  	/* Print info about runtime of triggers */
! 	if (es->printAnalyze)
  	{
  		ResultRelInfo *rInfo;
  		bool		show_relname;
--- 280,286 ----
  	}
  
  	/* Print info about runtime of triggers */
! 	if (stmt->analyze)
  	{
  		ResultRelInfo *rInfo;
  		bool		show_relname;
*************** ExplainOnePlan(PlannedStmt *plannedstmt,
*** 335,341 ****
  	do_text_output_multiline(tstate, buf.data);
  
  	pfree(buf.data);
! 	pfree(es);
  }
  
  /*
--- 325,350 ----
  	do_text_output_multiline(tstate, buf.data);
  
  	pfree(buf.data);
! }
! 
! /*
!  * ExplainOneResult -
!  *	  converts a Plan node into ascii string and appends it to 'str'
!  */
! void
! ExplainOneResult(StringInfo str, QueryDesc *queryDesc,
! 				 bool analyze, bool verbose)
! {
! 	ExplainState	es = { 0 };
! 
! 	es.printTList = verbose;
! 	es.printAnalyze = analyze;
! 	es.pstmt = queryDesc->plannedstmt;
! 	es.rtable = queryDesc->plannedstmt->rtable;
! 
! 	explain_outNode(str,
! 					queryDesc->plannedstmt->planTree, queryDesc->planstate,
! 					NULL, 0, &es);
  }
  
  /*
diff -cpr HEAD/src/backend/tcop/pquery.c auto_explain/src/backend/tcop/pquery.c
*** HEAD/src/backend/tcop/pquery.c	Fri Aug  1 22:16:09 2008
--- auto_explain/src/backend/tcop/pquery.c	Thu Oct  9 18:10:23 2008
***************
*** 32,38 ****
   * if there are several).
   */
  Portal		ActivePortal = NULL;
! 
  
  static void ProcessQuery(PlannedStmt *plan,
  			 ParamListInfo params,
--- 32,38 ----
   * if there are several).
   */
  Portal		ActivePortal = NULL;
! bool		force_instrument = false;
  
  static void ProcessQuery(PlannedStmt *plan,
  			 ParamListInfo params,
*************** CreateQueryDesc(PlannedStmt *plannedstmt
*** 76,82 ****
  	qd->crosscheck_snapshot = RegisterSnapshot(crosscheck_snapshot);
  	qd->dest = dest;			/* output dest */
  	qd->params = params;		/* parameter values passed into query */
! 	qd->doInstrument = doInstrument;	/* instrumentation wanted? */
  
  	/* null these fields until set by ExecutorStart */
  	qd->tupDesc = NULL;
--- 76,82 ----
  	qd->crosscheck_snapshot = RegisterSnapshot(crosscheck_snapshot);
  	qd->dest = dest;			/* output dest */
  	qd->params = params;		/* parameter values passed into query */
! 	qd->doInstrument = force_instrument || doInstrument;	/* instrumentation wanted? */
  
  	/* null these fields until set by ExecutorStart */
  	qd->tupDesc = NULL;
diff -cpr HEAD/src/backend/utils/misc/guc.c auto_explain/src/backend/utils/misc/guc.c
*** HEAD/src/backend/utils/misc/guc.c	Mon Oct  6 22:05:36 2008
--- auto_explain/src/backend/utils/misc/guc.c	Thu Oct  9 18:10:23 2008
*************** static const char *assign_pgstat_temp_di
*** 169,174 ****
--- 169,175 ----
  
  static char *config_enum_get_options(struct config_enum *record, 
  									 const char *prefix, const char *suffix);
+ static void initialize_option(struct config_generic *gconf);
  
  
  /*
*************** InitializeGUCOptions(void)
*** 3177,3288 ****
  	for (i = 0; i < num_guc_variables; i++)
  	{
  		struct config_generic *gconf = guc_variables[i];
! 
! 		gconf->status = 0;
! 		gconf->reset_source = PGC_S_DEFAULT;
! 		gconf->source = PGC_S_DEFAULT;
! 		gconf->stack = NULL;
! 		gconf->sourcefile = NULL;
! 		gconf->sourceline = 0;
! 
! 		switch (gconf->vartype)
! 		{
! 			case PGC_BOOL:
! 				{
! 					struct config_bool *conf = (struct config_bool *) gconf;
! 
! 					if (conf->assign_hook)
! 						if (!(*conf->assign_hook) (conf->boot_val, true,
! 												   PGC_S_DEFAULT))
! 							elog(FATAL, "failed to initialize %s to %d",
! 								 conf->gen.name, (int) conf->boot_val);
! 					*conf->variable = conf->reset_val = conf->boot_val;
! 					break;
! 				}
! 			case PGC_INT:
! 				{
! 					struct config_int *conf = (struct config_int *) gconf;
! 
! 					Assert(conf->boot_val >= conf->min);
! 					Assert(conf->boot_val <= conf->max);
! 					if (conf->assign_hook)
! 						if (!(*conf->assign_hook) (conf->boot_val, true,
! 												   PGC_S_DEFAULT))
! 							elog(FATAL, "failed to initialize %s to %d",
! 								 conf->gen.name, conf->boot_val);
! 					*conf->variable = conf->reset_val = conf->boot_val;
! 					break;
! 				}
! 			case PGC_REAL:
! 				{
! 					struct config_real *conf = (struct config_real *) gconf;
! 
! 					Assert(conf->boot_val >= conf->min);
! 					Assert(conf->boot_val <= conf->max);
! 					if (conf->assign_hook)
! 						if (!(*conf->assign_hook) (conf->boot_val, true,
! 												   PGC_S_DEFAULT))
! 							elog(FATAL, "failed to initialize %s to %g",
! 								 conf->gen.name, conf->boot_val);
! 					*conf->variable = conf->reset_val = conf->boot_val;
! 					break;
! 				}
! 			case PGC_STRING:
! 				{
! 					struct config_string *conf = (struct config_string *) gconf;
! 					char	   *str;
! 
! 					*conf->variable = NULL;
! 					conf->reset_val = NULL;
! 
! 					if (conf->boot_val == NULL)
! 					{
! 						/* leave the value NULL, do not call assign hook */
! 						break;
! 					}
! 
! 					str = guc_strdup(FATAL, conf->boot_val);
! 					conf->reset_val = str;
! 
! 					if (conf->assign_hook)
! 					{
! 						const char *newstr;
! 
! 						newstr = (*conf->assign_hook) (str, true,
! 													   PGC_S_DEFAULT);
! 						if (newstr == NULL)
! 						{
! 							elog(FATAL, "failed to initialize %s to \"%s\"",
! 								 conf->gen.name, str);
! 						}
! 						else if (newstr != str)
! 						{
! 							free(str);
! 
! 							/*
! 							 * See notes in set_config_option about casting
! 							 */
! 							str = (char *) newstr;
! 							conf->reset_val = str;
! 						}
! 					}
! 					*conf->variable = str;
! 					break;
! 				}
! 			case PGC_ENUM:
! 				{
! 					struct config_enum *conf = (struct config_enum *) gconf;
! 
! 					if (conf->assign_hook)
! 						if (!(*conf->assign_hook) (conf->boot_val, true,
! 												   PGC_S_DEFAULT))
! 							elog(FATAL, "failed to initialize %s to %s",
! 								 conf->gen.name, 
! 								 config_enum_lookup_by_value(conf, conf->boot_val));
! 					*conf->variable = conf->reset_val = conf->boot_val;
! 					break;
! 				}
! 		}
  	}
  
  	guc_dirty = false;
--- 3178,3184 ----
  	for (i = 0; i < num_guc_variables; i++)
  	{
  		struct config_generic *gconf = guc_variables[i];
! 		initialize_option(gconf);
  	}
  
  	guc_dirty = false;
*************** InitializeGUCOptions(void)
*** 3338,3343 ****
--- 3234,3348 ----
  	}
  }
  
+ static void
+ initialize_option(struct config_generic *gconf)
+ {
+ 	gconf->status = 0;
+ 	gconf->reset_source = PGC_S_DEFAULT;
+ 	gconf->source = PGC_S_DEFAULT;
+ 	gconf->stack = NULL;
+ 	gconf->sourcefile = NULL;
+ 	gconf->sourceline = 0;
+ 
+ 	switch (gconf->vartype)
+ 	{
+ 		case PGC_BOOL:
+ 			{
+ 				struct config_bool *conf = (struct config_bool *) gconf;
+ 
+ 				if (conf->assign_hook)
+ 					if (!(*conf->assign_hook) (conf->boot_val, true,
+ 											   PGC_S_DEFAULT))
+ 						elog(FATAL, "failed to initialize %s to %d",
+ 							 conf->gen.name, (int) conf->boot_val);
+ 				*conf->variable = conf->reset_val = conf->boot_val;
+ 				break;
+ 			}
+ 		case PGC_INT:
+ 			{
+ 				struct config_int *conf = (struct config_int *) gconf;
+ 
+ 				Assert(conf->boot_val >= conf->min);
+ 				Assert(conf->boot_val <= conf->max);
+ 				if (conf->assign_hook)
+ 					if (!(*conf->assign_hook) (conf->boot_val, true,
+ 											   PGC_S_DEFAULT))
+ 						elog(FATAL, "failed to initialize %s to %d",
+ 							 conf->gen.name, conf->boot_val);
+ 				*conf->variable = conf->reset_val = conf->boot_val;
+ 				break;
+ 			}
+ 		case PGC_REAL:
+ 			{
+ 				struct config_real *conf = (struct config_real *) gconf;
+ 
+ 				Assert(conf->boot_val >= conf->min);
+ 				Assert(conf->boot_val <= conf->max);
+ 				if (conf->assign_hook)
+ 					if (!(*conf->assign_hook) (conf->boot_val, true,
+ 											   PGC_S_DEFAULT))
+ 						elog(FATAL, "failed to initialize %s to %g",
+ 							 conf->gen.name, conf->boot_val);
+ 				*conf->variable = conf->reset_val = conf->boot_val;
+ 				break;
+ 			}
+ 		case PGC_STRING:
+ 			{
+ 				struct config_string *conf = (struct config_string *) gconf;
+ 				char	   *str;
+ 
+ 				*conf->variable = NULL;
+ 				conf->reset_val = NULL;
+ 
+ 				if (conf->boot_val == NULL)
+ 				{
+ 					/* leave the value NULL, do not call assign hook */
+ 					break;
+ 				}
+ 
+ 				str = guc_strdup(FATAL, conf->boot_val);
+ 				conf->reset_val = str;
+ 
+ 				if (conf->assign_hook)
+ 				{
+ 					const char *newstr;
+ 
+ 					newstr = (*conf->assign_hook) (str, true,
+ 												   PGC_S_DEFAULT);
+ 					if (newstr == NULL)
+ 					{
+ 						elog(FATAL, "failed to initialize %s to \"%s\"",
+ 							 conf->gen.name, str);
+ 					}
+ 					else if (newstr != str)
+ 					{
+ 						free(str);
+ 
+ 						/*
+ 						 * See notes in set_config_option about casting
+ 						 */
+ 						str = (char *) newstr;
+ 						conf->reset_val = str;
+ 					}
+ 				}
+ 				*conf->variable = str;
+ 				break;
+ 			}
+ 		case PGC_ENUM:
+ 			{
+ 				struct config_enum *conf = (struct config_enum *) gconf;
+ 
+ 				if (conf->assign_hook)
+ 					if (!(*conf->assign_hook) (conf->boot_val, true,
+ 											   PGC_S_DEFAULT))
+ 						elog(FATAL, "failed to initialize %s to %s",
+ 							 conf->gen.name, 
+ 							 config_enum_lookup_by_value(conf, conf->boot_val));
+ 				*conf->variable = conf->reset_val = conf->boot_val;
+ 				break;
+ 			}
+ 	}
+ }
  
  /*
   * Select the configuration files and data directory to be used, and
*************** define_custom_variable(struct config_gen
*** 5639,5644 ****
--- 5644,5650 ----
  	if (res == NULL)
  	{
  		/* No placeholder to replace, so just add it */
+ 		initialize_option(variable);
  		add_guc_variable(variable, ERROR);
  		return;
  	}
*************** define_custom_variable(struct config_gen
*** 5673,5678 ****
--- 5679,5686 ----
  		set_config_option(name, value,
  						  pHolder->gen.context, pHolder->gen.source,
  						  GUC_ACTION_SET, true);
+ 	else
+ 		initialize_option(variable);
  
  	/*
  	 * Free up as much as we conveniently can of the placeholder structure
*************** DefineCustomEnumVariable(const char *nam
*** 5804,5809 ****
--- 5812,5840 ----
  	var->assign_hook = assign_hook;
  	var->show_hook = show_hook;
  	define_custom_variable(&var->gen);
+ }
+ 
+ static const int config_varsize[] =
+ {
+ 	sizeof(struct config_bool),
+ 	sizeof(struct config_int),
+ 	sizeof(struct config_real),
+ 	sizeof(struct config_string),
+ 	sizeof(struct config_enum),
+ };
+ 
+ void
+ DefineCustomVariable(enum config_type type, const void *variable)
+ {
+ 	int		size = config_varsize[type];
+ 	const struct config_generic	   *var = variable;
+ 	struct config_generic		   *gen;
+ 
+ 	gen = (struct config_generic *) guc_malloc(ERROR, size);
+ 	memcpy(gen, var, size);
+ 	gen->name = guc_strdup(ERROR, var->name);
+ 	gen->vartype = type;
+ 	define_custom_variable(gen);
  }
  
  void
diff -cpr HEAD/src/include/commands/explain.h auto_explain/src/include/commands/explain.h
*** HEAD/src/include/commands/explain.h	Wed Jan  2 04:45:57 2008
--- auto_explain/src/include/commands/explain.h	Thu Oct  9 18:10:23 2008
*************** extern void ExplainOneUtility(Node *util
*** 41,44 ****
--- 41,47 ----
  extern void ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
  			   ExplainStmt *stmt, TupOutputState *tstate);
  
+ extern void ExplainOneResult(StringInfo str, QueryDesc *queryDesc,
+ 							 bool analyze, bool verbose);
+ 
  #endif   /* EXPLAIN_H */
diff -cpr HEAD/src/include/executor/execdesc.h auto_explain/src/include/executor/execdesc.h
*** HEAD/src/include/executor/execdesc.h	Wed Jan  2 04:45:57 2008
--- auto_explain/src/include/executor/execdesc.h	Thu Oct  9 18:10:23 2008
***************
*** 20,25 ****
--- 20,27 ----
  #include "tcop/dest.h"
  
  
+ extern PGDLLIMPORT bool force_instrument;
+ 
  /* ----------------
   *		query descriptor:
   *
diff -cpr HEAD/src/include/utils/guc_tables.h auto_explain/src/include/utils/guc_tables.h
*** HEAD/src/include/utils/guc_tables.h	Tue Sep 30 19:52:14 2008
--- auto_explain/src/include/utils/guc_tables.h	Thu Oct  9 18:10:23 2008
*************** extern const char *config_enum_lookup_by
*** 242,246 ****
--- 242,247 ----
  extern bool config_enum_lookup_by_name(struct config_enum *record,
  									  const char *value, int *retval);
  
+ extern void DefineCustomVariable(enum config_type type, const void *variable);
  
  #endif   /* GUC_TABLES_H */

diff --git a/contrib/Makefile b/contrib/Makefile
index 30f75c7..b25af3c 100644
--- a/contrib/Makefile
+++ b/contrib/Makefile
@@ -6,6 +6,7 @@ include $(top_builddir)/src/Makefile.global
 
 WANTED_DIRS = \
 		adminpack	\
+		auto_explain	\
 		btree_gist	\
 		chkpass		\
 		citext		\
diff --git a/contrib/auto_explain/Makefile b/contrib/auto_explain/Makefile
new file mode 100644
index 0000000..0d0ccc2
--- /dev/null
+++ b/contrib/auto_explain/Makefile
@@ -0,0 +1,13 @@
+MODULE_big = auto_explain
+OBJS = auto_explain.o
+
+ifdef USE_PGXS
+PG_CONFIG = pg_config
+PGXS := $(shell $(PG_CONFIG) --pgxs)
+include $(PGXS)
+else
+subdir = contrib/auto_explain
+top_builddir = ../..
+include $(top_builddir)/src/Makefile.global
+include $(top_srcdir)/contrib/contrib-global.mk
+endif
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
new file mode 100644
index 0000000..9bbff01
--- /dev/null
+++ b/contrib/auto_explain/auto_explain.c
@@ -0,0 +1,194 @@
+/*
+ * auto_explain.c
+ */
+#include "postgres.h"
+
+#include "commands/explain.h"
+#include "executor/instrument.h"
+#include "miscadmin.h"
+#include "utils/guc_tables.h"
+
+PG_MODULE_MAGIC;
+
+#define GUCNAME(name)		("explain." name)
+
+static int		explain_log_min_duration = -1;	/* msec or -1 */
+static bool		explain_log_analyze = false;
+static bool		explain_log_verbose = false;
+
+static bool		toplevel = true;
+static ExecutorRun_hook_type	prev_ExecutorRun = NULL;
+
+void	_PG_init(void);
+void	_PG_fini(void);
+
+static TupleTableSlot *explain_ExecutorRun(QueryDesc *queryDesc,
+										   ScanDirection direction,
+										   long count);
+static bool assign_log_min_duration(int newval, bool doit, GucSource source);
+static bool assign_log_analyze(bool newval, bool doit, GucSource source);
+static bool assign_log_verbose(bool newval, bool doit, GucSource source);
+
+static struct config_int def_log_min_duration =
+{
+	{
+		GUCNAME("log_min_duration"),
+		PGC_USERSET,
+		STATS_MONITORING,
+		"Sets the minimum execution time above which plans will be logged.",
+		"Zero prints all plans. -1 turns this feature off.",
+		GUC_UNIT_MS
+	},
+	&explain_log_min_duration,
+	-1, -1, INT_MAX / 1000, assign_log_min_duration, NULL
+};
+
+static struct config_bool def_log_analyze =
+{
+	{
+		GUCNAME("log_analyze"),
+		PGC_USERSET,
+		STATS_MONITORING,
+		"Use EXPLAIN ANALYZE for plan logging."
+	},
+	&explain_log_analyze,
+	false, assign_log_analyze, NULL
+};
+
+static struct config_bool def_log_verbose =
+{
+	{
+		GUCNAME("log_verbose"),
+		PGC_USERSET,
+		STATS_MONITORING,
+		"Use EXPLAIN VERBOSE for plan logging."
+	},
+	&explain_log_verbose,
+	false, assign_log_verbose, NULL
+};
+
+void
+_PG_init(void)
+{
+	DefineCustomVariable(PGC_INT, &def_log_min_duration);
+	DefineCustomVariable(PGC_BOOL, &def_log_analyze);
+	DefineCustomVariable(PGC_BOOL, &def_log_verbose);
+
+	/* install ExecutorRun_hook */
+	prev_ExecutorRun = ExecutorRun_hook;
+	ExecutorRun_hook = explain_ExecutorRun;
+}
+
+void
+_PG_fini(void)
+{
+	/* uninstall ExecutorRun_hook */
+	ExecutorRun_hook = prev_ExecutorRun;
+}
+
+TupleTableSlot *
+explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, long count)
+{
+	TupleTableSlot *result;
+	
+	if (toplevel && explain_log_min_duration >= 0)
+	{
+		instr_time		starttime;
+		instr_time		duration;
+		double			msec;
+
+		/* Disable our hooks temporarily during the top-level query. */
+		toplevel = false;
+		PG_TRY();
+		{
+			INSTR_TIME_SET_CURRENT(starttime);
+
+			if (prev_ExecutorRun)
+				result = prev_ExecutorRun(queryDesc, direction, count);
+			else
+				result = standard_ExecutorRun(queryDesc, direction, count);
+
+			INSTR_TIME_SET_CURRENT(duration);
+			INSTR_TIME_SUBTRACT(duration, starttime);
+			msec = INSTR_TIME_GET_MILLISEC(duration);
+
+			/* Log plan if duration is exceeded. */
+			if (msec > explain_log_min_duration)
+			{
+				StringInfoData	buf;
+
+				initStringInfo(&buf);
+				ExplainOneResult(&buf, queryDesc,
+					queryDesc->doInstrument && explain_log_analyze,
+					explain_log_verbose);
+
+				/* Remove last line break */
+				if (buf.len > 0 && buf.data[buf.len - 1] == '\n')
+				{
+					buf.data[buf.len - 1] = '\0';
+					buf.len--;
+				}
+				ereport(LOG,
+						(errmsg("duration: %.3f ms  plan:\n%s",
+								msec, buf.data)));
+
+				pfree(buf.data);
+			}
+
+			toplevel = true;
+		}
+		PG_CATCH();
+		{
+			toplevel = true;
+			PG_RE_THROW();
+		}
+		PG_END_TRY();
+	}
+	else
+	{
+		/* ignore recursive executions, that are typically function calls */
+		if (prev_ExecutorRun)
+			result = prev_ExecutorRun(queryDesc, direction, count);
+		else
+			result = standard_ExecutorRun(queryDesc, direction, count);
+	}
+
+	return result;
+}
+
+/* Emulate PGC_SUSET for custom variables. */
+static bool
+suset_assign(GucSource source, const char *name)
+{
+	if (source >= PGC_S_CLIENT && !superuser())
+	{
+		ereport(GUC_complaint_elevel(source),
+				(errcode(ERRCODE_INSUFFICIENT_PRIVILEGE),
+				 errmsg("permission denied to set parameter \"%s\"", name)));
+		return false;
+	}
+
+	return true;
+}
+
+static bool
+assign_log_min_duration(int newval, bool doit, GucSource source)
+{
+	if (!suset_assign(source, GUCNAME("log_min_duration")))
+		return false;
+	if (doit)
+		force_instrument = (newval >= 0);
+	return true;
+}
+
+static bool
+assign_log_analyze(bool newval, bool doit, GucSource source)
+{
+	return suset_assign(source, GUCNAME("log_analyze"));
+}
+
+static bool
+assign_log_verbose(bool newval, bool doit, GucSource source)
+{
+	return suset_assign(source, GUCNAME("log_verbose"));
+}
diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml
new file mode 100644
index 0000000..ea8da3b
--- /dev/null
+++ b/doc/src/sgml/auto-explain.sgml
@@ -0,0 +1,136 @@
+<sect1 id="autoexplain">
+ <title>auto_explain</title>
+
+ <indexterm zone="autoexplain">
+  <primary>auto_explain</primary>
+ </indexterm>
+
+ <para>
+  The <filename>auto_explain</filename> module provides a means for
+  logging execution plans that execution times are longer than configuration.
+ </para>
+
+ <para>
+  You can <command>LOAD</> this module dynamically or preload it automatically with
+  <varname>shared_preload_libraries</> or <varname>local_preload_libraries</>.
+ </para>
+
+ <sect2>
+  <title>The <structname>auto_explain</structname> view</title>
+
+  <para>
+   The definitions of the columns exposed by the view are:
+  </para>
+
+  <para>
+   There is one row for each statement. Statements are grouped when they have
+   same SQL text, are in the same database, and are executed by the same user.
+  </para>
+
+  <para>
+   Because of security restriction, non-super users cannot see query strings
+   executed by other users.
+  </para>
+ </sect2>
+
+ <sect2>
+  <title>Configuration parameters</title>
+
+  <variablelist>
+   <varlistentry>
+    <term>
+     <varname>explain.log_min_duration</varname> (<type>integer</type>)
+    </term>
+    <listitem>
+     <para>
+      <varname>explain.log_min_duration</varname> is the minimum execution time
+      in milliseconds which execution plan will be logged. Setting this to zero
+      prints all plans. Minus-one (the default) disables logging plans.
+      For example, if you set it to <literal>250ms</literal> then all plan
+      that run 250ms or longer in executor will be logged.
+      Enabling this parameter can be helpful in tracking down unoptimized queries
+      in your applications. Only superusers can change this setting.
+     </para>
+    </listitem>
+   </varlistentry>
+
+   <varlistentry>
+    <term>
+     <varname>explain.log_analyze</varname> (<type>boolean</type>)
+    </term>
+
+    <listitem>
+     <para>
+      <varname>explain.log_analyze</varname> enables to use EXPLAIN ANALYZE when
+      an execution plan is logged by <varname>explain.log_min_duration</varname>.
+      This parameter is off by default. Only superusers can change this setting.
+     </para>
+     <para>
+      NOTE: If you set the parameter on, instrument timers are enabled even if
+      you don't use EXPLAIN ANALYZE. This has some overhead to execute plans.
+     </para>
+    </listitem>
+   </varlistentry>
+
+   <varlistentry>
+    <term>
+     <varname>explain.log_verbose</varname> (<type>boolean</type>)
+    </term>
+
+    <listitem>
+     <para>
+      <varname>explain.log_verbose</varname> enables to use EXPLAIN VERBOSE when
+      an execution plan is logged by <varname>explain.log_min_duration</varname>.
+      This parameter is off by default. Only superusers can change this setting.
+     </para>
+    </listitem>
+   </varlistentry>
+  </variablelist>
+
+  <para>
+   If you set these explain.* parameters in your postgresql.conf,
+   you also need to add 'explain' in <varname>custom_variable_classes</>.
+  </para>
+
+  <programlisting>
+  # postgresql.conf
+  shared_preload_libraries = 'auto_explain'
+  
+  custom_variable_classes = 'explain'
+  explain.log_min_duration = 3s
+  </programlisting>
+ </sect2>
+
+ <sect2>
+  <title>Sample output</title>
+
+  <programlisting>
+  postgres=# LOAD 'auto_explain';
+  postgres=# SET explain.log_min_duration = 0;
+  postgres=# SELECT count(*)
+               FROM pg_class, pg_index
+              WHERE oid = indrelid AND indisunique;
+  
+  LOG:  duration: 0.986 ms  plan:
+          Aggregate  (cost=14.90..14.91 rows=1 width=0)
+            ->  Hash Join  (cost=3.91..14.70 rows=81 width=0)
+                  Hash Cond: (pg_class.oid = pg_index.indrelid)
+                  ->  Seq Scan on pg_class  (cost=0.00..8.27 rows=227 width=4)
+                  ->  Hash  (cost=2.90..2.90 rows=81 width=4)
+                        ->  Seq Scan on pg_index  (cost=0.00..2.90 rows=81 width=4)
+                              Filter: indisunique
+  STATEMENT:  SELECT count(*)
+            FROM pg_class, pg_index
+           WHERE oid = indrelid AND indisunique;
+  </programlisting>
+ </sect2>
+
+ <sect2>
+  <title>Authors</title>
+
+  <para>
+   Takahiro Itagaki <email>itagaki.takahiro@oss.ntt.co.jp</email>
+  </para>
+ </sect2>
+
+</sect1>
diff --git a/doc/src/sgml/contrib.sgml b/doc/src/sgml/contrib.sgml
index 72d8828..0108da3 100644
--- a/doc/src/sgml/contrib.sgml
+++ b/doc/src/sgml/contrib.sgml
@@ -79,6 +79,7 @@ psql -d dbname -f <replaceable>SHAREDIR</>/contrib/<replaceable>module</>.sql
  </para>
 
  &adminpack;
+ &auto-explain;
  &btree-gist;
  &chkpass;
  &citext;
diff --git a/doc/src/sgml/filelist.sgml b/doc/src/sgml/filelist.sgml
index b0538b6..68db2b9 100644
--- a/doc/src/sgml/filelist.sgml
+++ b/doc/src/sgml/filelist.sgml
@@ -92,6 +92,7 @@
 <!-- contrib information -->
 <!entity contrib         SYSTEM "contrib.sgml">
 <!entity adminpack       SYSTEM "adminpack.sgml">
+<!entity auto-explain    SYSTEM "auto-explain.sgml">
 <!entity btree-gist      SYSTEM "btree-gist.sgml">
 <!entity chkpass         SYSTEM "chkpass.sgml">
 <!entity citext          SYSTEM "citext.sgml">
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index c0c53cf..4d46a34 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -224,7 +224,6 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
 	QueryDesc  *queryDesc;
 	instr_time	starttime;
 	double		totaltime = 0;
-	ExplainState *es;
 	StringInfoData buf;
 	int			eflags;
 
@@ -265,17 +264,8 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
 		totaltime += elapsed_time(&starttime);
 	}
 
-	es = (ExplainState *) palloc0(sizeof(ExplainState));
-
-	es->printTList = stmt->verbose;
-	es->printAnalyze = stmt->analyze;
-	es->pstmt = queryDesc->plannedstmt;
-	es->rtable = queryDesc->plannedstmt->rtable;
-
 	initStringInfo(&buf);
-	explain_outNode(&buf,
-					queryDesc->plannedstmt->planTree, queryDesc->planstate,
-					NULL, 0, es);
+	ExplainOneResult(&buf, queryDesc, stmt->analyze, stmt->verbose);
 
 	/*
 	 * If we ran the command, run any AFTER triggers it queued.  (Note this
@@ -290,7 +280,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
 	}
 
 	/* Print info about runtime of triggers */
-	if (es->printAnalyze)
+	if (stmt->analyze)
 	{
 		ResultRelInfo *rInfo;
 		bool		show_relname;
@@ -335,7 +325,26 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
 	do_text_output_multiline(tstate, buf.data);
 
 	pfree(buf.data);
-	pfree(es);
+}
+
+/*
+ * ExplainOneResult -
+ *	  converts a Plan node into ascii string and appends it to 'str'
+ */
+void
+ExplainOneResult(StringInfo str, QueryDesc *queryDesc,
+				 bool analyze, bool verbose)
+{
+	ExplainState	es = { 0 };
+
+	es.printTList = verbose;
+	es.printAnalyze = analyze;
+	es.pstmt = queryDesc->plannedstmt;
+	es.rtable = queryDesc->plannedstmt->rtable;
+
+	explain_outNode(str,
+					queryDesc->plannedstmt->planTree, queryDesc->planstate,
+					NULL, 0, &es);
 }
 
 /*
diff --git a/src/backend/tcop/pquery.c b/src/backend/tcop/pquery.c
index a933d3c..ff2df9b 100644
--- a/src/backend/tcop/pquery.c
+++ b/src/backend/tcop/pquery.c
@@ -32,7 +32,7 @@
  * if there are several).
  */
 Portal		ActivePortal = NULL;
-
+bool		force_instrument = false;
 
 static void ProcessQuery(PlannedStmt *plan,
 			 ParamListInfo params,
@@ -76,7 +76,7 @@ CreateQueryDesc(PlannedStmt *plannedstmt,
 	qd->crosscheck_snapshot = RegisterSnapshot(crosscheck_snapshot);
 	qd->dest = dest;			/* output dest */
 	qd->params = params;		/* parameter values passed into query */
-	qd->doInstrument = doInstrument;	/* instrumentation wanted? */
+	qd->doInstrument = force_instrument || doInstrument;	/* instrumentation wanted? */
 
 	/* null these fields until set by ExecutorStart */
 	qd->tupDesc = NULL;
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 58851e5..015f06d 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -169,6 +169,7 @@ static const char *assign_pgstat_temp_directory(const char *newval, bool doit, G
 
 static char *config_enum_get_options(struct config_enum *record, 
 									 const char *prefix, const char *suffix);
+static void initialize_option(struct config_generic *gconf);
 
 
 /*
@@ -3177,112 +3178,7 @@ InitializeGUCOptions(void)
 	for (i = 0; i < num_guc_variables; i++)
 	{
 		struct config_generic *gconf = guc_variables[i];
-
-		gconf->status = 0;
-		gconf->reset_source = PGC_S_DEFAULT;
-		gconf->source = PGC_S_DEFAULT;
-		gconf->stack = NULL;
-		gconf->sourcefile = NULL;
-		gconf->sourceline = 0;
-
-		switch (gconf->vartype)
-		{
-			case PGC_BOOL:
-				{
-					struct config_bool *conf = (struct config_bool *) gconf;
-
-					if (conf->assign_hook)
-						if (!(*conf->assign_hook) (conf->boot_val, true,
-												   PGC_S_DEFAULT))
-							elog(FATAL, "failed to initialize %s to %d",
-								 conf->gen.name, (int) conf->boot_val);
-					*conf->variable = conf->reset_val = conf->boot_val;
-					break;
-				}
-			case PGC_INT:
-				{
-					struct config_int *conf = (struct config_int *) gconf;
-
-					Assert(conf->boot_val >= conf->min);
-					Assert(conf->boot_val <= conf->max);
-					if (conf->assign_hook)
-						if (!(*conf->assign_hook) (conf->boot_val, true,
-												   PGC_S_DEFAULT))
-							elog(FATAL, "failed to initialize %s to %d",
-								 conf->gen.name, conf->boot_val);
-					*conf->variable = conf->reset_val = conf->boot_val;
-					break;
-				}
-			case PGC_REAL:
-				{
-					struct config_real *conf = (struct config_real *) gconf;
-
-					Assert(conf->boot_val >= conf->min);
-					Assert(conf->boot_val <= conf->max);
-					if (conf->assign_hook)
-						if (!(*conf->assign_hook) (conf->boot_val, true,
-												   PGC_S_DEFAULT))
-							elog(FATAL, "failed to initialize %s to %g",
-								 conf->gen.name, conf->boot_val);
-					*conf->variable = conf->reset_val = conf->boot_val;
-					break;
-				}
-			case PGC_STRING:
-				{
-					struct config_string *conf = (struct config_string *) gconf;
-					char	   *str;
-
-					*conf->variable = NULL;
-					conf->reset_val = NULL;
-
-					if (conf->boot_val == NULL)
-					{
-						/* leave the value NULL, do not call assign hook */
-						break;
-					}
-
-					str = guc_strdup(FATAL, conf->boot_val);
-					conf->reset_val = str;
-
-					if (conf->assign_hook)
-					{
-						const char *newstr;
-
-						newstr = (*conf->assign_hook) (str, true,
-													   PGC_S_DEFAULT);
-						if (newstr == NULL)
-						{
-							elog(FATAL, "failed to initialize %s to \"%s\"",
-								 conf->gen.name, str);
-						}
-						else if (newstr != str)
-						{
-							free(str);
-
-							/*
-							 * See notes in set_config_option about casting
-							 */
-							str = (char *) newstr;
-							conf->reset_val = str;
-						}
-					}
-					*conf->variable = str;
-					break;
-				}
-			case PGC_ENUM:
-				{
-					struct config_enum *conf = (struct config_enum *) gconf;
-
-					if (conf->assign_hook)
-						if (!(*conf->assign_hook) (conf->boot_val, true,
-												   PGC_S_DEFAULT))
-							elog(FATAL, "failed to initialize %s to %s",
-								 conf->gen.name, 
-								 config_enum_lookup_by_value(conf, conf->boot_val));
-					*conf->variable = conf->reset_val = conf->boot_val;
-					break;
-				}
-		}
+		initialize_option(gconf);
 	}
 
 	guc_dirty = false;
@@ -3338,6 +3234,115 @@ InitializeGUCOptions(void)
 	}
 }
 
+static void
+initialize_option(struct config_generic *gconf)
+{
+	gconf->status = 0;
+	gconf->reset_source = PGC_S_DEFAULT;
+	gconf->source = PGC_S_DEFAULT;
+	gconf->stack = NULL;
+	gconf->sourcefile = NULL;
+	gconf->sourceline = 0;
+
+	switch (gconf->vartype)
+	{
+		case PGC_BOOL:
+			{
+				struct config_bool *conf = (struct config_bool *) gconf;
+
+				if (conf->assign_hook)
+					if (!(*conf->assign_hook) (conf->boot_val, true,
+											   PGC_S_DEFAULT))
+						elog(FATAL, "failed to initialize %s to %d",
+							 conf->gen.name, (int) conf->boot_val);
+				*conf->variable = conf->reset_val = conf->boot_val;
+				break;
+			}
+		case PGC_INT:
+			{
+				struct config_int *conf = (struct config_int *) gconf;
+
+				Assert(conf->boot_val >= conf->min);
+				Assert(conf->boot_val <= conf->max);
+				if (conf->assign_hook)
+					if (!(*conf->assign_hook) (conf->boot_val, true,
+											   PGC_S_DEFAULT))
+						elog(FATAL, "failed to initialize %s to %d",
+							 conf->gen.name, conf->boot_val);
+				*conf->variable = conf->reset_val = conf->boot_val;
+				break;
+			}
+		case PGC_REAL:
+			{
+				struct config_real *conf = (struct config_real *) gconf;
+
+				Assert(conf->boot_val >= conf->min);
+				Assert(conf->boot_val <= conf->max);
+				if (conf->assign_hook)
+					if (!(*conf->assign_hook) (conf->boot_val, true,
+											   PGC_S_DEFAULT))
+						elog(FATAL, "failed to initialize %s to %g",
+							 conf->gen.name, conf->boot_val);
+				*conf->variable = conf->reset_val = conf->boot_val;
+				break;
+			}
+		case PGC_STRING:
+			{
+				struct config_string *conf = (struct config_string *) gconf;
+				char	   *str;
+
+				*conf->variable = NULL;
+				conf->reset_val = NULL;
+
+				if (conf->boot_val == NULL)
+				{
+					/* leave the value NULL, do not call assign hook */
+					break;
+				}
+
+				str = guc_strdup(FATAL, conf->boot_val);
+				conf->reset_val = str;
+
+				if (conf->assign_hook)
+				{
+					const char *newstr;
+
+					newstr = (*conf->assign_hook) (str, true,
+												   PGC_S_DEFAULT);
+					if (newstr == NULL)
+					{
+						elog(FATAL, "failed to initialize %s to \"%s\"",
+							 conf->gen.name, str);
+					}
+					else if (newstr != str)
+					{
+						free(str);
+
+						/*
+						 * See notes in set_config_option about casting
+						 */
+						str = (char *) newstr;
+						conf->reset_val = str;
+					}
+				}
+				*conf->variable = str;
+				break;
+			}
+		case PGC_ENUM:
+			{
+				struct config_enum *conf = (struct config_enum *) gconf;
+
+				if (conf->assign_hook)
+					if (!(*conf->assign_hook) (conf->boot_val, true,
+											   PGC_S_DEFAULT))
+						elog(FATAL, "failed to initialize %s to %s",
+							 conf->gen.name, 
+							 config_enum_lookup_by_value(conf, conf->boot_val));
+				*conf->variable = conf->reset_val = conf->boot_val;
+				break;
+			}
+	}
+}
 
 /*
  * Select the configuration files and data directory to be used, and
@@ -5639,6 +5644,7 @@ define_custom_variable(struct config_generic * variable)
 	if (res == NULL)
 	{
 		/* No placeholder to replace, so just add it */
+		initialize_option(variable);
 		add_guc_variable(variable, ERROR);
 		return;
 	}
@@ -5673,6 +5679,8 @@ define_custom_variable(struct config_generic * variable)
 		set_config_option(name, value,
 						  pHolder->gen.context, pHolder->gen.source,
 						  GUC_ACTION_SET, true);
+	else
+		initialize_option(variable);
 
 	/*
 	 * Free up as much as we conveniently can of the placeholder structure
@@ -5806,6 +5814,29 @@ DefineCustomEnumVariable(const char *name,
 	define_custom_variable(&var->gen);
 }
 
+static const int config_varsize[] =
+{
+	sizeof(struct config_bool),
+	sizeof(struct config_int),
+	sizeof(struct config_real),
+	sizeof(struct config_string),
+	sizeof(struct config_enum),
+};
+
+void
+DefineCustomVariable(enum config_type type, const void *variable)
+{
+	int		size = config_varsize[type];
+	const struct config_generic	   *var = variable;
+	struct config_generic		   *gen;
+
+	gen = (struct config_generic *) guc_malloc(ERROR, size);
+	memcpy(gen, var, size);
+	gen->name = guc_strdup(ERROR, var->name);
+	gen->vartype = type;
+	define_custom_variable(gen);
+}
+
 void
 EmitWarningsOnPlaceholders(const char *className)
 {
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 5b808d5..cf07915 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -41,4 +41,7 @@ extern void ExplainOneUtility(Node *utilityStmt, ExplainStmt *stmt,
 extern void ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
 			   ExplainStmt *stmt, TupOutputState *tstate);
 
+extern void ExplainOneResult(StringInfo str, QueryDesc *queryDesc,
+							 bool analyze, bool verbose);
+
 #endif   /* EXPLAIN_H */
diff --git a/src/include/executor/execdesc.h b/src/include/executor/execdesc.h
index 2e2c159..854721c 100644
--- a/src/include/executor/execdesc.h
+++ b/src/include/executor/execdesc.h
@@ -20,6 +20,8 @@
 #include "tcop/dest.h"
 
 
+extern PGDLLIMPORT bool force_instrument;
+
 /* ----------------
  *		query descriptor:
  *
diff --git a/src/include/utils/guc_tables.h b/src/include/utils/guc_tables.h
index 8791660..3982a27 100644
--- a/src/include/utils/guc_tables.h
+++ b/src/include/utils/guc_tables.h
@@ -242,5 +242,6 @@ extern const char *config_enum_lookup_by_value(struct config_enum *record, int v
 extern bool config_enum_lookup_by_name(struct config_enum *record,
 									  const char *value, int *retval);
 
+extern void DefineCustomVariable(enum config_type type, const void *variable);
 
 #endif   /* GUC_TABLES_H */

*** a/contrib/auto_explain/auto_explain.c
--- b/contrib/auto_explain/auto_explain.c
***************
*** 15,20 **** PG_MODULE_MAGIC;
--- 15,21 ----
  static int		explain_log_min_duration = -1;	/* msec or -1 */
  static bool		explain_log_analyze = false;
  static bool		explain_log_verbose = false;
+ static bool		explain_log_nested = false;
  
  static bool		toplevel = true;
  static ExecutorRun_hook_type	prev_ExecutorRun = NULL;
***************
*** 28,33 **** static void explain_ExecutorRun(QueryDesc *queryDesc,
--- 29,35 ----
  static bool assign_log_min_duration(int newval, bool doit, GucSource source);
  static bool assign_log_analyze(bool newval, bool doit, GucSource source);
  static bool assign_log_verbose(bool newval, bool doit, GucSource source);
+ static bool assign_log_nested(bool newval, bool doit, GucSource source);
  
  static struct config_int def_log_min_duration =
  {
***************
*** 67,78 **** static struct config_bool def_log_verbose =
--- 69,93 ----
  	false, assign_log_verbose, NULL
  };
  
+ static struct config_bool def_log_nested_statements =
+ {
+ 	{
+ 		GUCNAME("log_nested_statements"),
+ 		PGC_USERSET,
+ 		STATS_MONITORING,
+ 		"Log nested statements."
+ 	},
+ 	&explain_log_nested,
+ 	false, assign_log_nested, NULL
+ };
+ 
  void
  _PG_init(void)
  {
  	DefineCustomVariable(PGC_INT, &def_log_min_duration);
  	DefineCustomVariable(PGC_BOOL, &def_log_analyze);
  	DefineCustomVariable(PGC_BOOL, &def_log_verbose);
+ 	DefineCustomVariable(PGC_BOOL, &def_log_nested_statements);
  
  	/* install ExecutorRun_hook */
  	prev_ExecutorRun = ExecutorRun_hook;
***************
*** 89,95 **** _PG_fini(void)
  void
  explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, long count)
  {
! 	if (toplevel && explain_log_min_duration >= 0)
  	{
  		instr_time		starttime;
  		instr_time		duration;
--- 104,110 ----
  void
  explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, long count)
  {
! 	if ((toplevel || explain_log_nested) && explain_log_min_duration >= 0)
  	{
  		instr_time		starttime;
  		instr_time		duration;
***************
*** 188,190 **** assign_log_verbose(bool newval, bool doit, GucSource source)
--- 203,211 ----
  {
  	return suset_assign(source, GUCNAME("log_verbose"));
  }
+ 
+ static bool
+ assign_log_nested(bool newval, bool doit, GucSource source)
+ {
+ 	return suset_assign(source, GUCNAME("log_nested_statements"));
+ }

diff --git a/contrib/Makefile b/contrib/Makefile
index 30f75c7..b25af3c 100644
--- a/contrib/Makefile
+++ b/contrib/Makefile
@@ -6,6 +6,7 @@ include $(top_builddir)/src/Makefile.global
 
 WANTED_DIRS = \
 		adminpack	\
+		auto_explain	\
 		btree_gist	\
 		chkpass		\
 		citext		\
diff --git a/contrib/auto_explain/Makefile b/contrib/auto_explain/Makefile
new file mode 100644
index 0000000..0d0ccc2
--- /dev/null
+++ b/contrib/auto_explain/Makefile
@@ -0,0 +1,13 @@
+MODULE_big = auto_explain
+OBJS = auto_explain.o
+
+ifdef USE_PGXS
+PG_CONFIG = pg_config
+PGXS := $(shell $(PG_CONFIG) --pgxs)
+include $(PGXS)
+else
+subdir = contrib/auto_explain
+top_builddir = ../..
+include $(top_builddir)/src/Makefile.global
+include $(top_srcdir)/contrib/contrib-global.mk
+endif
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
new file mode 100644
index 0000000..5f582c3
--- /dev/null
+++ b/contrib/auto_explain/auto_explain.c
@@ -0,0 +1,213 @@
+/*
+ * auto_explain.c
+ */
+#include "postgres.h"
+
+#include "commands/explain.h"
+#include "executor/instrument.h"
+#include "miscadmin.h"
+#include "utils/guc_tables.h"
+
+PG_MODULE_MAGIC;
+
+#define GUCNAME(name)		("explain." name)
+
+static int		explain_log_min_duration = -1;	/* msec or -1 */
+static bool		explain_log_analyze = false;
+static bool		explain_log_verbose = false;
+static bool		explain_log_nested = false;
+
+static bool		toplevel = true;
+static ExecutorRun_hook_type	prev_ExecutorRun = NULL;
+
+void	_PG_init(void);
+void	_PG_fini(void);
+
+static void explain_ExecutorRun(QueryDesc *queryDesc,
+										   ScanDirection direction,
+										   long count);
+static bool assign_log_min_duration(int newval, bool doit, GucSource source);
+static bool assign_log_analyze(bool newval, bool doit, GucSource source);
+static bool assign_log_verbose(bool newval, bool doit, GucSource source);
+static bool assign_log_nested(bool newval, bool doit, GucSource source);
+
+static struct config_int def_log_min_duration =
+{
+	{
+		GUCNAME("log_min_duration"),
+		PGC_USERSET,
+		STATS_MONITORING,
+		"Sets the minimum execution time above which plans will be logged.",
+		"Zero prints all plans. -1 turns this feature off.",
+		GUC_UNIT_MS
+	},
+	&explain_log_min_duration,
+	-1, -1, INT_MAX / 1000, assign_log_min_duration, NULL
+};
+
+static struct config_bool def_log_analyze =
+{
+	{
+		GUCNAME("log_analyze"),
+		PGC_USERSET,
+		STATS_MONITORING,
+		"Use EXPLAIN ANALYZE for plan logging."
+	},
+	&explain_log_analyze,
+	false, assign_log_analyze, NULL
+};
+
+static struct config_bool def_log_verbose =
+{
+	{
+		GUCNAME("log_verbose"),
+		PGC_USERSET,
+		STATS_MONITORING,
+		"Use EXPLAIN VERBOSE for plan logging."
+	},
+	&explain_log_verbose,
+	false, assign_log_verbose, NULL
+};
+
+static struct config_bool def_log_nested_statements =
+{
+	{
+		GUCNAME("log_nested_statements"),
+		PGC_USERSET,
+		STATS_MONITORING,
+		"Log nested statements."
+	},
+	&explain_log_nested,
+	false, assign_log_nested, NULL
+};
+
+void
+_PG_init(void)
+{
+	DefineCustomVariable(PGC_INT, &def_log_min_duration);
+	DefineCustomVariable(PGC_BOOL, &def_log_analyze);
+	DefineCustomVariable(PGC_BOOL, &def_log_verbose);
+	DefineCustomVariable(PGC_BOOL, &def_log_nested_statements);
+
+	/* install ExecutorRun_hook */
+	prev_ExecutorRun = ExecutorRun_hook;
+	ExecutorRun_hook = explain_ExecutorRun;
+}
+
+void
+_PG_fini(void)
+{
+	/* uninstall ExecutorRun_hook */
+	ExecutorRun_hook = prev_ExecutorRun;
+}
+
+void
+explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, long count)
+{
+	if ((toplevel || explain_log_nested) && explain_log_min_duration >= 0)
+	{
+		instr_time		starttime;
+		instr_time		duration;
+		double			msec;
+
+		/* Disable our hooks temporarily during the top-level query. */
+		toplevel = false;
+		PG_TRY();
+		{
+			INSTR_TIME_SET_CURRENT(starttime);
+
+			if (prev_ExecutorRun)
+				prev_ExecutorRun(queryDesc, direction, count);
+			else
+				standard_ExecutorRun(queryDesc, direction, count);
+
+			INSTR_TIME_SET_CURRENT(duration);
+			INSTR_TIME_SUBTRACT(duration, starttime);
+			msec = INSTR_TIME_GET_MILLISEC(duration);
+
+			/* Log plan if duration is exceeded. */
+			if (msec > explain_log_min_duration)
+			{
+				StringInfoData	buf;
+
+				initStringInfo(&buf);
+				ExplainOneResult(&buf, queryDesc,
+					queryDesc->doInstrument && explain_log_analyze,
+					explain_log_verbose);
+
+				/* Remove last line break */
+				if (buf.len > 0 && buf.data[buf.len - 1] == '\n')
+				{
+					buf.data[buf.len - 1] = '\0';
+					buf.len--;
+				}
+				ereport(LOG,
+						(errmsg("duration: %.3f ms  plan:\n%s",
+								msec, buf.data)));
+
+				pfree(buf.data);
+			}
+
+			toplevel = true;
+		}
+		PG_CATCH();
+		{
+			toplevel = true;
+			PG_RE_THROW();
+		}
+		PG_END_TRY();
+	}
+	else
+	{
+		/* ignore recursive executions, that are typically function calls */
+		if (prev_ExecutorRun)
+			prev_ExecutorRun(queryDesc, direction, count);
+		else
+			standard_ExecutorRun(queryDesc, direction, count);
+	}
+
+	return;
+}
+
+/* Emulate PGC_SUSET for custom variables. */
+static bool
+suset_assign(GucSource source, const char *name)
+{
+	if (source >= PGC_S_CLIENT && !superuser())
+	{
+		ereport(GUC_complaint_elevel(source),
+				(errcode(ERRCODE_INSUFFICIENT_PRIVILEGE),
+				 errmsg("permission denied to set parameter \"%s\"", name)));
+		return false;
+	}
+
+	return true;
+}
+
+static bool
+assign_log_min_duration(int newval, bool doit, GucSource source)
+{
+	if (!suset_assign(source, GUCNAME("log_min_duration")))
+		return false;
+	if (doit)
+		force_instrument = (newval >= 0);
+	return true;
+}
+
+static bool
+assign_log_analyze(bool newval, bool doit, GucSource source)
+{
+	return suset_assign(source, GUCNAME("log_analyze"));
+}
+
+static bool
+assign_log_verbose(bool newval, bool doit, GucSource source)
+{
+	return suset_assign(source, GUCNAME("log_verbose"));
+}
+
+static bool
+assign_log_nested(bool newval, bool doit, GucSource source)
+{
+	return suset_assign(source, GUCNAME("log_nested_statements"));
+}
diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml
new file mode 100644
index 0000000..ea8da3b
--- /dev/null
+++ b/doc/src/sgml/auto-explain.sgml
@@ -0,0 +1,136 @@
+<sect1 id="autoexplain">
+ <title>auto_explain</title>
+
+ <indexterm zone="autoexplain">
+  <primary>auto_explain</primary>
+ </indexterm>
+
+ <para>
+  The <filename>auto_explain</filename> module provides a means for
+  logging execution plans that execution times are longer than configuration.
+ </para>
+
+ <para>
+  You can <command>LOAD</> this module dynamically or preload it automatically with
+  <varname>shared_preload_libraries</> or <varname>local_preload_libraries</>.
+ </para>
+
+ <sect2>
+  <title>The <structname>auto_explain</structname> view</title>
+
+  <para>
+   The definitions of the columns exposed by the view are:
+  </para>
+
+  <para>
+   There is one row for each statement. Statements are grouped when they have
+   same SQL text, are in the same database, and are executed by the same user.
+  </para>
+
+  <para>
+   Because of security restriction, non-super users cannot see query strings
+   executed by other users.
+  </para>
+ </sect2>
+
+ <sect2>
+  <title>Configuration parameters</title>
+
+  <variablelist>
+   <varlistentry>
+    <term>
+     <varname>explain.log_min_duration</varname> (<type>integer</type>)
+    </term>
+    <listitem>
+     <para>
+      <varname>explain.log_min_duration</varname> is the minimum execution time
+      in milliseconds which execution plan will be logged. Setting this to zero
+      prints all plans. Minus-one (the default) disables logging plans.
+      For example, if you set it to <literal>250ms</literal> then all plan
+      that run 250ms or longer in executor will be logged.
+      Enabling this parameter can be helpful in tracking down unoptimized queries
+      in your applications. Only superusers can change this setting.
+     </para>
+    </listitem>
+   </varlistentry>
+
+   <varlistentry>
+    <term>
+     <varname>explain.log_analyze</varname> (<type>boolean</type>)
+    </term>
+
+    <listitem>
+     <para>
+      <varname>explain.log_analyze</varname> enables to use EXPLAIN ANALYZE when
+      an execution plan is logged by <varname>explain.log_min_duration</varname>.
+      This parameter is off by default. Only superusers can change this setting.
+     </para>
+     <para>
+      NOTE: If you set the parameter on, instrument timers are enabled even if
+      you don't use EXPLAIN ANALYZE. This has some overhead to execute plans.
+     </para>
+    </listitem>
+   </varlistentry>
+
+   <varlistentry>
+    <term>
+     <varname>explain.log_verbose</varname> (<type>boolean</type>)
+    </term>
+
+    <listitem>
+     <para>
+      <varname>explain.log_verbose</varname> enables to use EXPLAIN VERBOSE when
+      an execution plan is logged by <varname>explain.log_min_duration</varname>.
+      This parameter is off by default. Only superusers can change this setting.
+     </para>
+    </listitem>
+   </varlistentry>
+  </variablelist>
+
+  <para>
+   If you set these explain.* parameters in your postgresql.conf,
+   you also need to add 'explain' in <varname>custom_variable_classes</>.
+  </para>
+
+  <programlisting>
+  # postgresql.conf
+  shared_preload_libraries = 'auto_explain'
+  
+  custom_variable_classes = 'explain'
+  explain.log_min_duration = 3s
+  </programlisting>
+ </sect2>
+
+ <sect2>
+  <title>Sample output</title>
+
+  <programlisting>
+  postgres=# LOAD 'auto_explain';
+  postgres=# SET explain.log_min_duration = 0;
+  postgres=# SELECT count(*)
+               FROM pg_class, pg_index
+              WHERE oid = indrelid AND indisunique;
+  
+  LOG:  duration: 0.986 ms  plan:
+          Aggregate  (cost=14.90..14.91 rows=1 width=0)
+            ->  Hash Join  (cost=3.91..14.70 rows=81 width=0)
+                  Hash Cond: (pg_class.oid = pg_index.indrelid)
+                  ->  Seq Scan on pg_class  (cost=0.00..8.27 rows=227 width=4)
+                  ->  Hash  (cost=2.90..2.90 rows=81 width=4)
+                        ->  Seq Scan on pg_index  (cost=0.00..2.90 rows=81 width=4)
+                              Filter: indisunique
+  STATEMENT:  SELECT count(*)
+            FROM pg_class, pg_index
+           WHERE oid = indrelid AND indisunique;
+  </programlisting>
+ </sect2>
+
+ <sect2>
+  <title>Authors</title>
+
+  <para>
+   Takahiro Itagaki <email>itagaki.takahiro@oss.ntt.co.jp</email>
+  </para>
+ </sect2>
+
+</sect1>
diff --git a/doc/src/sgml/contrib.sgml b/doc/src/sgml/contrib.sgml
index 72d8828..0108da3 100644
--- a/doc/src/sgml/contrib.sgml
+++ b/doc/src/sgml/contrib.sgml
@@ -79,6 +79,7 @@ psql -d dbname -f <replaceable>SHAREDIR</>/contrib/<replaceable>module</>.sql
  </para>
 
  &adminpack;
+ &auto-explain;
  &btree-gist;
  &chkpass;
  &citext;
diff --git a/doc/src/sgml/filelist.sgml b/doc/src/sgml/filelist.sgml
index b0538b6..68db2b9 100644
--- a/doc/src/sgml/filelist.sgml
+++ b/doc/src/sgml/filelist.sgml
@@ -92,6 +92,7 @@
 <!-- contrib information -->
 <!entity contrib         SYSTEM "contrib.sgml">
 <!entity adminpack       SYSTEM "adminpack.sgml">
+<!entity auto-explain    SYSTEM "auto-explain.sgml">
 <!entity btree-gist      SYSTEM "btree-gist.sgml">
 <!entity chkpass         SYSTEM "chkpass.sgml">
 <!entity citext          SYSTEM "citext.sgml">
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index c0c53cf..4d46a34 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -224,7 +224,6 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
 	QueryDesc  *queryDesc;
 	instr_time	starttime;
 	double		totaltime = 0;
-	ExplainState *es;
 	StringInfoData buf;
 	int			eflags;
 
@@ -265,17 +264,8 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
 		totaltime += elapsed_time(&starttime);
 	}
 
-	es = (ExplainState *) palloc0(sizeof(ExplainState));
-
-	es->printTList = stmt->verbose;
-	es->printAnalyze = stmt->analyze;
-	es->pstmt = queryDesc->plannedstmt;
-	es->rtable = queryDesc->plannedstmt->rtable;
-
 	initStringInfo(&buf);
-	explain_outNode(&buf,
-					queryDesc->plannedstmt->planTree, queryDesc->planstate,
-					NULL, 0, es);
+	ExplainOneResult(&buf, queryDesc, stmt->analyze, stmt->verbose);
 
 	/*
 	 * If we ran the command, run any AFTER triggers it queued.  (Note this
@@ -290,7 +280,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
 	}
 
 	/* Print info about runtime of triggers */
-	if (es->printAnalyze)
+	if (stmt->analyze)
 	{
 		ResultRelInfo *rInfo;
 		bool		show_relname;
@@ -335,7 +325,26 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
 	do_text_output_multiline(tstate, buf.data);
 
 	pfree(buf.data);
-	pfree(es);
+}
+
+/*
+ * ExplainOneResult -
+ *	  converts a Plan node into ascii string and appends it to 'str'
+ */
+void
+ExplainOneResult(StringInfo str, QueryDesc *queryDesc,
+				 bool analyze, bool verbose)
+{
+	ExplainState	es = { 0 };
+
+	es.printTList = verbose;
+	es.printAnalyze = analyze;
+	es.pstmt = queryDesc->plannedstmt;
+	es.rtable = queryDesc->plannedstmt->rtable;
+
+	explain_outNode(str,
+					queryDesc->plannedstmt->planTree, queryDesc->planstate,
+					NULL, 0, &es);
 }
 
 /*
diff --git a/src/backend/tcop/pquery.c b/src/backend/tcop/pquery.c
index a933d3c..ff2df9b 100644
--- a/src/backend/tcop/pquery.c
+++ b/src/backend/tcop/pquery.c
@@ -32,7 +32,7 @@
  * if there are several).
  */
 Portal		ActivePortal = NULL;
-
+bool		force_instrument = false;
 
 static void ProcessQuery(PlannedStmt *plan,
 			 ParamListInfo params,
@@ -76,7 +76,7 @@ CreateQueryDesc(PlannedStmt *plannedstmt,
 	qd->crosscheck_snapshot = RegisterSnapshot(crosscheck_snapshot);
 	qd->dest = dest;			/* output dest */
 	qd->params = params;		/* parameter values passed into query */
-	qd->doInstrument = doInstrument;	/* instrumentation wanted? */
+	qd->doInstrument = force_instrument || doInstrument;	/* instrumentation wanted? */
 
 	/* null these fields until set by ExecutorStart */
 	qd->tupDesc = NULL;
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 58851e5..015f06d 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -169,6 +169,7 @@ static const char *assign_pgstat_temp_directory(const char *newval, bool doit, G
 
 static char *config_enum_get_options(struct config_enum *record, 
 									 const char *prefix, const char *suffix);
+static void initialize_option(struct config_generic *gconf);
 
 
 /*
@@ -3177,112 +3178,7 @@ InitializeGUCOptions(void)
 	for (i = 0; i < num_guc_variables; i++)
 	{
 		struct config_generic *gconf = guc_variables[i];
-
-		gconf->status = 0;
-		gconf->reset_source = PGC_S_DEFAULT;
-		gconf->source = PGC_S_DEFAULT;
-		gconf->stack = NULL;
-		gconf->sourcefile = NULL;
-		gconf->sourceline = 0;
-
-		switch (gconf->vartype)
-		{
-			case PGC_BOOL:
-				{
-					struct config_bool *conf = (struct config_bool *) gconf;
-
-					if (conf->assign_hook)
-						if (!(*conf->assign_hook) (conf->boot_val, true,
-												   PGC_S_DEFAULT))
-							elog(FATAL, "failed to initialize %s to %d",
-								 conf->gen.name, (int) conf->boot_val);
-					*conf->variable = conf->reset_val = conf->boot_val;
-					break;
-				}
-			case PGC_INT:
-				{
-					struct config_int *conf = (struct config_int *) gconf;
-
-					Assert(conf->boot_val >= conf->min);
-					Assert(conf->boot_val <= conf->max);
-					if (conf->assign_hook)
-						if (!(*conf->assign_hook) (conf->boot_val, true,
-												   PGC_S_DEFAULT))
-							elog(FATAL, "failed to initialize %s to %d",
-								 conf->gen.name, conf->boot_val);
-					*conf->variable = conf->reset_val = conf->boot_val;
-					break;
-				}
-			case PGC_REAL:
-				{
-					struct config_real *conf = (struct config_real *) gconf;
-
-					Assert(conf->boot_val >= conf->min);
-					Assert(conf->boot_val <= conf->max);
-					if (conf->assign_hook)
-						if (!(*conf->assign_hook) (conf->boot_val, true,
-												   PGC_S_DEFAULT))
-							elog(FATAL, "failed to initialize %s to %g",
-								 conf->gen.name, conf->boot_val);
-					*conf->variable = conf->reset_val = conf->boot_val;
-					break;
-				}
-			case PGC_STRING:
-				{
-					struct config_string *conf = (struct config_string *) gconf;
-					char	   *str;
-
-					*conf->variable = NULL;
-					conf->reset_val = NULL;
-
-					if (conf->boot_val == NULL)
-					{
-						/* leave the value NULL, do not call assign hook */
-						break;
-					}
-
-					str = guc_strdup(FATAL, conf->boot_val);
-					conf->reset_val = str;
-
-					if (conf->assign_hook)
-					{
-						const char *newstr;
-
-						newstr = (*conf->assign_hook) (str, true,
-													   PGC_S_DEFAULT);
-						if (newstr == NULL)
-						{
-							elog(FATAL, "failed to initialize %s to \"%s\"",
-								 conf->gen.name, str);
-						}
-						else if (newstr != str)
-						{
-							free(str);
-
-							/*
-							 * See notes in set_config_option about casting
-							 */
-							str = (char *) newstr;
-							conf->reset_val = str;
-						}
-					}
-					*conf->variable = str;
-					break;
-				}
-			case PGC_ENUM:
-				{
-					struct config_enum *conf = (struct config_enum *) gconf;
-
-					if (conf->assign_hook)
-						if (!(*conf->assign_hook) (conf->boot_val, true,
-												   PGC_S_DEFAULT))
-							elog(FATAL, "failed to initialize %s to %s",
-								 conf->gen.name, 
-								 config_enum_lookup_by_value(conf, conf->boot_val));
-					*conf->variable = conf->reset_val = conf->boot_val;
-					break;
-				}
-		}
+		initialize_option(gconf);
 	}
 
 	guc_dirty = false;
@@ -3338,6 +3234,115 @@ InitializeGUCOptions(void)
 	}
 }
 
+static void
+initialize_option(struct config_generic *gconf)
+{
+	gconf->status = 0;
+	gconf->reset_source = PGC_S_DEFAULT;
+	gconf->source = PGC_S_DEFAULT;
+	gconf->stack = NULL;
+	gconf->sourcefile = NULL;
+	gconf->sourceline = 0;
+
+	switch (gconf->vartype)
+	{
+		case PGC_BOOL:
+			{
+				struct config_bool *conf = (struct config_bool *) gconf;
+
+				if (conf->assign_hook)
+					if (!(*conf->assign_hook) (conf->boot_val, true,
+											   PGC_S_DEFAULT))
+						elog(FATAL, "failed to initialize %s to %d",
+							 conf->gen.name, (int) conf->boot_val);
+				*conf->variable = conf->reset_val = conf->boot_val;
+				break;
+			}
+		case PGC_INT:
+			{
+				struct config_int *conf = (struct config_int *) gconf;
+
+				Assert(conf->boot_val >= conf->min);
+				Assert(conf->boot_val <= conf->max);
+				if (conf->assign_hook)
+					if (!(*conf->assign_hook) (conf->boot_val, true,
+											   PGC_S_DEFAULT))
+						elog(FATAL, "failed to initialize %s to %d",
+							 conf->gen.name, conf->boot_val);
+				*conf->variable = conf->reset_val = conf->boot_val;
+				break;
+			}
+		case PGC_REAL:
+			{
+				struct config_real *conf = (struct config_real *) gconf;
+
+				Assert(conf->boot_val >= conf->min);
+				Assert(conf->boot_val <= conf->max);
+				if (conf->assign_hook)
+					if (!(*conf->assign_hook) (conf->boot_val, true,
+											   PGC_S_DEFAULT))
+						elog(FATAL, "failed to initialize %s to %g",
+							 conf->gen.name, conf->boot_val);
+				*conf->variable = conf->reset_val = conf->boot_val;
+				break;
+			}
+		case PGC_STRING:
+			{
+				struct config_string *conf = (struct config_string *) gconf;
+				char	   *str;
+
+				*conf->variable = NULL;
+				conf->reset_val = NULL;
+
+				if (conf->boot_val == NULL)
+				{
+					/* leave the value NULL, do not call assign hook */
+					break;
+				}
+
+				str = guc_strdup(FATAL, conf->boot_val);
+				conf->reset_val = str;
+
+				if (conf->assign_hook)
+				{
+					const char *newstr;
+
+					newstr = (*conf->assign_hook) (str, true,
+												   PGC_S_DEFAULT);
+					if (newstr == NULL)
+					{
+						elog(FATAL, "failed to initialize %s to \"%s\"",
+							 conf->gen.name, str);
+					}
+					else if (newstr != str)
+					{
+						free(str);
+
+						/*
+						 * See notes in set_config_option about casting
+						 */
+						str = (char *) newstr;
+						conf->reset_val = str;
+					}
+				}
+				*conf->variable = str;
+				break;
+			}
+		case PGC_ENUM:
+			{
+				struct config_enum *conf = (struct config_enum *) gconf;
+
+				if (conf->assign_hook)
+					if (!(*conf->assign_hook) (conf->boot_val, true,
+											   PGC_S_DEFAULT))
+						elog(FATAL, "failed to initialize %s to %s",
+							 conf->gen.name, 
+							 config_enum_lookup_by_value(conf, conf->boot_val));
+				*conf->variable = conf->reset_val = conf->boot_val;
+				break;
+			}
+	}
+}
 
 /*
  * Select the configuration files and data directory to be used, and
@@ -5639,6 +5644,7 @@ define_custom_variable(struct config_generic * variable)
 	if (res == NULL)
 	{
 		/* No placeholder to replace, so just add it */
+		initialize_option(variable);
 		add_guc_variable(variable, ERROR);
 		return;
 	}
@@ -5673,6 +5679,8 @@ define_custom_variable(struct config_generic * variable)
 		set_config_option(name, value,
 						  pHolder->gen.context, pHolder->gen.source,
 						  GUC_ACTION_SET, true);
+	else
+		initialize_option(variable);
 
 	/*
 	 * Free up as much as we conveniently can of the placeholder structure
@@ -5806,6 +5814,29 @@ DefineCustomEnumVariable(const char *name,
 	define_custom_variable(&var->gen);
 }
 
+static const int config_varsize[] =
+{
+	sizeof(struct config_bool),
+	sizeof(struct config_int),
+	sizeof(struct config_real),
+	sizeof(struct config_string),
+	sizeof(struct config_enum),
+};
+
+void
+DefineCustomVariable(enum config_type type, const void *variable)
+{
+	int		size = config_varsize[type];
+	const struct config_generic	   *var = variable;
+	struct config_generic		   *gen;
+
+	gen = (struct config_generic *) guc_malloc(ERROR, size);
+	memcpy(gen, var, size);
+	gen->name = guc_strdup(ERROR, var->name);
+	gen->vartype = type;
+	define_custom_variable(gen);
+}
+
 void
 EmitWarningsOnPlaceholders(const char *className)
 {
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 5b808d5..cf07915 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -41,4 +41,7 @@ extern void ExplainOneUtility(Node *utilityStmt, ExplainStmt *stmt,
 extern void ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
 			   ExplainStmt *stmt, TupOutputState *tstate);
 
+extern void ExplainOneResult(StringInfo str, QueryDesc *queryDesc,
+							 bool analyze, bool verbose);
+
 #endif   /* EXPLAIN_H */
diff --git a/src/include/executor/execdesc.h b/src/include/executor/execdesc.h
index 2e2c159..854721c 100644
--- a/src/include/executor/execdesc.h
+++ b/src/include/executor/execdesc.h
@@ -20,6 +20,8 @@
 #include "tcop/dest.h"
 
 
+extern PGDLLIMPORT bool force_instrument;
+
 /* ----------------
  *		query descriptor:
  *
diff --git a/src/include/utils/guc_tables.h b/src/include/utils/guc_tables.h
index 8791660..3982a27 100644
--- a/src/include/utils/guc_tables.h
+++ b/src/include/utils/guc_tables.h
@@ -242,5 +242,6 @@ extern const char *config_enum_lookup_by_value(struct config_enum *record, int v
 extern bool config_enum_lookup_by_name(struct config_enum *record,
 									  const char *value, int *retval);
 
+extern void DefineCustomVariable(enum config_type type, const void *variable);
 
 #endif   /* GUC_TABLES_H */

diff -cprN HEAD/contrib/Makefile auto-explain/contrib/Makefile
*** HEAD/contrib/Makefile	Wed Jul 30 03:31:20 2008
--- auto-explain/contrib/Makefile	Mon Nov 10 17:55:49 2008
*************** include $(top_builddir)/src/Makefile.glo
*** 6,11 ****
--- 6,12 ----
  
  WANTED_DIRS = \
  		adminpack	\
+ 		auto_explain	\
  		btree_gist	\
  		chkpass		\
  		citext		\
diff -cprN HEAD/contrib/auto_explain/Makefile auto-explain/contrib/auto_explain/Makefile
*** HEAD/contrib/auto_explain/Makefile	Thu Jan  1 09:00:00 1970
--- auto-explain/contrib/auto_explain/Makefile	Mon Nov 10 17:29:01 2008
***************
*** 0 ****
--- 1,13 ----
+ MODULE_big = auto_explain
+ OBJS = auto_explain.o
+ 
+ ifdef USE_PGXS
+ PG_CONFIG = pg_config
+ PGXS := $(shell $(PG_CONFIG) --pgxs)
+ include $(PGXS)
+ else
+ subdir = contrib/auto_explain
+ top_builddir = ../..
+ include $(top_builddir)/src/Makefile.global
+ include $(top_srcdir)/contrib/contrib-global.mk
+ endif
diff -cprN HEAD/contrib/auto_explain/auto_explain.c auto-explain/contrib/auto_explain/auto_explain.c
*** HEAD/contrib/auto_explain/auto_explain.c	Thu Jan  1 09:00:00 1970
--- auto-explain/contrib/auto_explain/auto_explain.c	Mon Nov 10 17:52:03 2008
***************
*** 0 ****
--- 1,215 ----
+ /*
+  * auto_explain.c
+  */
+ #include "postgres.h"
+ 
+ #include "commands/explain.h"
+ #include "executor/instrument.h"
+ #include "miscadmin.h"
+ #include "utils/guc_tables.h"
+ 
+ PG_MODULE_MAGIC;
+ 
+ #define GUCNAME(name)		("explain." name)
+ 
+ static int		explain_log_min_duration = -1;	/* msec or -1 */
+ static bool		explain_log_analyze = false;
+ static bool		explain_log_verbose = false;
+ static bool		explain_log_nested = false;
+ 
+ static bool		toplevel = true;
+ static ExecutorRun_hook_type	prev_ExecutorRun = NULL;
+ 
+ void	_PG_init(void);
+ void	_PG_fini(void);
+ 
+ static void explain_ExecutorRun(QueryDesc *queryDesc,
+ 								ScanDirection direction,
+ 								long count);
+ static bool assign_log_min_duration(int newval, bool doit, GucSource source);
+ static bool assign_log_analyze(bool newval, bool doit, GucSource source);
+ static bool assign_log_verbose(bool newval, bool doit, GucSource source);
+ static bool assign_log_nested(bool newval, bool doit, GucSource source);
+ 
+ static struct config_int def_log_min_duration =
+ {
+ 	{
+ 		GUCNAME("log_min_duration"),
+ 		PGC_USERSET,
+ 		STATS_MONITORING,
+ 		"Sets the minimum execution time above which plans will be logged.",
+ 		"Zero prints all plans. -1 turns this feature off.",
+ 		GUC_UNIT_MS
+ 	},
+ 	&explain_log_min_duration,
+ 	-1, -1, INT_MAX / 1000, assign_log_min_duration, NULL
+ };
+ 
+ static struct config_bool def_log_analyze =
+ {
+ 	{
+ 		GUCNAME("log_analyze"),
+ 		PGC_USERSET,
+ 		STATS_MONITORING,
+ 		"Use EXPLAIN ANALYZE for plan logging."
+ 	},
+ 	&explain_log_analyze,
+ 	false, assign_log_analyze, NULL
+ };
+ 
+ static struct config_bool def_log_verbose =
+ {
+ 	{
+ 		GUCNAME("log_verbose"),
+ 		PGC_USERSET,
+ 		STATS_MONITORING,
+ 		"Use EXPLAIN VERBOSE for plan logging."
+ 	},
+ 	&explain_log_verbose,
+ 	false, assign_log_verbose, NULL
+ };
+ 
+ static struct config_bool def_log_nested_statements =
+ {
+ 	{
+ 		GUCNAME("log_nested_statements"),
+ 		PGC_USERSET,
+ 		STATS_MONITORING,
+ 		"Log nested statements."
+ 	},
+ 	&explain_log_nested,
+ 	false, assign_log_nested, NULL
+ };
+ 
+ void
+ _PG_init(void)
+ {
+ 	DefineCustomVariable(PGC_INT, &def_log_min_duration);
+ 	DefineCustomVariable(PGC_BOOL, &def_log_analyze);
+ 	DefineCustomVariable(PGC_BOOL, &def_log_verbose);
+ 	DefineCustomVariable(PGC_BOOL, &def_log_nested_statements);
+ 
+ 	/* install ExecutorRun_hook */
+ 	prev_ExecutorRun = ExecutorRun_hook;
+ 	ExecutorRun_hook = explain_ExecutorRun;
+ }
+ 
+ void
+ _PG_fini(void)
+ {
+ 	/* uninstall ExecutorRun_hook */
+ 	ExecutorRun_hook = prev_ExecutorRun;
+ }
+ 
+ void
+ explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, long count)
+ {
+ 	if ((toplevel || explain_log_nested) && explain_log_min_duration >= 0)
+ 	{
+ 		instr_time		starttime;
+ 		instr_time		duration;
+ 		double			msec;
+ 
+ 		/* Disable our hooks temporarily during the top-level query. */
+ 		toplevel = false;
+ 		PG_TRY();
+ 		{
+ 			INSTR_TIME_SET_CURRENT(starttime);
+ 
+ 			if (prev_ExecutorRun)
+ 				prev_ExecutorRun(queryDesc, direction, count);
+ 			else
+ 				standard_ExecutorRun(queryDesc, direction, count);
+ 
+ 			INSTR_TIME_SET_CURRENT(duration);
+ 			INSTR_TIME_SUBTRACT(duration, starttime);
+ 			msec = INSTR_TIME_GET_MILLISEC(duration);
+ 
+ 			/* Log plan if duration is exceeded. */
+ 			if (msec > explain_log_min_duration)
+ 			{
+ 				StringInfoData	buf;
+ 
+ 				initStringInfo(&buf);
+ 				ExplainOneResult(&buf, queryDesc,
+ 					queryDesc->doInstrument && explain_log_analyze,
+ 					explain_log_verbose);
+ 
+ 				/* Remove last line break */
+ 				if (buf.len > 0 && buf.data[buf.len - 1] == '\n')
+ 				{
+ 					buf.data[buf.len - 1] = '\0';
+ 					buf.len--;
+ 				}
+ 				ereport(LOG,
+ 						(errmsg("duration: %.3f ms  plan:\n%s",
+ 								msec, buf.data)));
+ 
+ 				pfree(buf.data);
+ 			}
+ 
+ 			toplevel = true;
+ 		}
+ 		PG_CATCH();
+ 		{
+ 			toplevel = true;
+ 			PG_RE_THROW();
+ 		}
+ 		PG_END_TRY();
+ 	}
+ 	else
+ 	{
+ 		/* ignore recursive executions, that are typically function calls */
+ 		if (prev_ExecutorRun)
+ 			prev_ExecutorRun(queryDesc, direction, count);
+ 		else
+ 			standard_ExecutorRun(queryDesc, direction, count);
+ 	}
+ }
+ 
+ /* Emulate PGC_SUSET for custom variables. */
+ static bool
+ suset_assign(GucSource source, const char *name)
+ {
+ 	if (source >= PGC_S_CLIENT && !superuser())
+ 	{
+ 		ereport(GUC_complaint_elevel(source),
+ 				(errcode(ERRCODE_INSUFFICIENT_PRIVILEGE),
+ 				 errmsg("permission denied to set parameter \"%s\"", name)));
+ 		return false;
+ 	}
+ 
+ 	return true;
+ }
+ 
+ static bool
+ assign_log_min_duration(int newval, bool doit, GucSource source)
+ {
+ 	if (!suset_assign(source, GUCNAME("log_min_duration")))
+ 		return false;
+ 	if (doit)
+ 		force_instrument = (newval >= 0 && explain_log_analyze);
+ 	return true;
+ }
+ 
+ static bool
+ assign_log_analyze(bool newval, bool doit, GucSource source)
+ {
+ 	if (!suset_assign(source, GUCNAME("log_analyze")))
+ 		return false;
+ 	if (doit)
+ 		force_instrument = (explain_log_min_duration >= 0 && newval);
+ 	return true;
+ }
+ 
+ static bool
+ assign_log_verbose(bool newval, bool doit, GucSource source)
+ {
+ 	return suset_assign(source, GUCNAME("log_verbose"));
+ }
+ 
+ static bool
+ assign_log_nested(bool newval, bool doit, GucSource source)
+ {
+ 	return suset_assign(source, GUCNAME("log_nested_statements"));
+ }
diff -cprN HEAD/doc/src/sgml/auto-explain.sgml auto-explain/doc/src/sgml/auto-explain.sgml
*** HEAD/doc/src/sgml/auto-explain.sgml	Thu Jan  1 09:00:00 1970
--- auto-explain/doc/src/sgml/auto-explain.sgml	Mon Nov 10 17:43:33 2008
***************
*** 0 ****
--- 1,150 ----
+ <sect1 id="autoexplain">
+  <title>auto_explain</title>
+ 
+  <indexterm zone="autoexplain">
+   <primary>auto_explain</primary>
+  </indexterm>
+ 
+  <para>
+   The <filename>auto_explain</filename> module provides a means for
+   logging execution plans that execution times are longer than configuration.
+  </para>
+ 
+  <para>
+   You can <command>LOAD</> this module dynamically or preload it automatically with
+   <varname>shared_preload_libraries</> or <varname>local_preload_libraries</>.
+  </para>
+ 
+  <sect2>
+   <title>The <structname>auto_explain</structname> view</title>
+ 
+   <para>
+    The definitions of the columns exposed by the view are:
+   </para>
+ 
+   <para>
+    There is one row for each statement. Statements are grouped when they have
+    same SQL text, are in the same database, and are executed by the same user.
+   </para>
+ 
+   <para>
+    Because of security restriction, non-super users cannot see query strings
+    executed by other users.
+   </para>
+  </sect2>
+ 
+  <sect2>
+   <title>Configuration parameters</title>
+ 
+   <variablelist>
+    <varlistentry>
+     <term>
+      <varname>explain.log_min_duration</varname> (<type>integer</type>)
+     </term>
+     <listitem>
+      <para>
+       <varname>explain.log_min_duration</varname> is the minimum execution time
+       in milliseconds which execution plan will be logged. Setting this to zero
+       prints all plans. Minus-one (the default) disables logging plans.
+       For example, if you set it to <literal>250ms</literal> then all plan
+       that run 250ms or longer in executor will be logged.
+       Enabling this parameter can be helpful in tracking down unoptimized queries
+       in your applications. Only superusers can change this setting.
+      </para>
+     </listitem>
+    </varlistentry>
+ 
+    <varlistentry>
+     <term>
+      <varname>explain.log_analyze</varname> (<type>boolean</type>)
+     </term>
+ 
+     <listitem>
+      <para>
+       <varname>explain.log_analyze</varname> enables to use EXPLAIN ANALYZE when
+       an execution plan is logged by <varname>explain.log_min_duration</varname>.
+       This parameter is off by default. Only superusers can change this setting.
+      </para>
+      <para>
+       NOTE: If you set the parameter on, instrument timers are enabled even if
+       you don't use EXPLAIN ANALYZE. This has some overhead to execute plans.
+      </para>
+     </listitem>
+    </varlistentry>
+ 
+    <varlistentry>
+     <term>
+      <varname>explain.log_verbose</varname> (<type>boolean</type>)
+     </term>
+ 
+     <listitem>
+      <para>
+       <varname>explain.log_verbose</varname> enables to use EXPLAIN VERBOSE when
+       an execution plan is logged by <varname>explain.log_min_duration</varname>.
+       This parameter is off by default. Only superusers can change this setting.
+      </para>
+     </listitem>
+    </varlistentry>
+ 
+    <varlistentry>
+     <term>
+      <varname>explain.log_nested_statements</varname> (<type>boolean</type>)
+     </term>
+ 
+     <listitem>
+      <para>
+       <varname>explain.log_nested_statements</varname> enables to log plans of
+       nested statements. If the value if off, only top-level plans are logged.
+       This parameter is off by default. Only superusers can change this setting.
+      </para>
+     </listitem>
+    </varlistentry>
+   </variablelist>
+ 
+   <para>
+    If you set these explain.* parameters in your postgresql.conf,
+    you also need to add 'explain' in <varname>custom_variable_classes</>.
+   </para>
+ 
+   <programlisting>
+   # postgresql.conf
+   shared_preload_libraries = 'auto_explain'
+   
+   custom_variable_classes = 'explain'
+   explain.log_min_duration = 3s
+   </programlisting>
+  </sect2>
+ 
+  <sect2>
+   <title>Sample output</title>
+ 
+   <programlisting>
+   postgres=# LOAD 'auto_explain';
+   postgres=# SET explain.log_min_duration = 0;
+   postgres=# SELECT count(*)
+                FROM pg_class, pg_index
+               WHERE oid = indrelid AND indisunique;
+   
+   LOG:  duration: 0.986 ms  plan:
+           Aggregate  (cost=14.90..14.91 rows=1 width=0)
+             ->  Hash Join  (cost=3.91..14.70 rows=81 width=0)
+                   Hash Cond: (pg_class.oid = pg_index.indrelid)
+                   ->  Seq Scan on pg_class  (cost=0.00..8.27 rows=227 width=4)
+                   ->  Hash  (cost=2.90..2.90 rows=81 width=4)
+                         ->  Seq Scan on pg_index  (cost=0.00..2.90 rows=81 width=4)
+                               Filter: indisunique
+   STATEMENT:  SELECT count(*)
+             FROM pg_class, pg_index
+            WHERE oid = indrelid AND indisunique;
+   </programlisting>
+  </sect2>
+ 
+  <sect2>
+   <title>Authors</title>
+ 
+   <para>
+    Takahiro Itagaki <email>itagaki.takahiro@oss.ntt.co.jp</email>
+   </para>
+  </sect2>
+ 
+ </sect1>
diff -cprN HEAD/doc/src/sgml/contrib.sgml auto-explain/doc/src/sgml/contrib.sgml
*** HEAD/doc/src/sgml/contrib.sgml	Wed Jul 30 03:31:20 2008
--- auto-explain/doc/src/sgml/contrib.sgml	Mon Nov 10 17:55:49 2008
*************** psql -d dbname -f <replaceable>SHAREDIR<
*** 79,84 ****
--- 79,85 ----
   </para>
  
   &adminpack;
+  &auto-explain;
   &btree-gist;
   &chkpass;
   &citext;
diff -cprN HEAD/doc/src/sgml/filelist.sgml auto-explain/doc/src/sgml/filelist.sgml
*** HEAD/doc/src/sgml/filelist.sgml	Wed Jul 30 03:31:20 2008
--- auto-explain/doc/src/sgml/filelist.sgml	Mon Nov 10 17:55:49 2008
***************
*** 92,97 ****
--- 92,98 ----
  <!-- contrib information -->
  <!entity contrib         SYSTEM "contrib.sgml">
  <!entity adminpack       SYSTEM "adminpack.sgml">
+ <!entity auto-explain    SYSTEM "auto-explain.sgml">
  <!entity btree-gist      SYSTEM "btree-gist.sgml">
  <!entity chkpass         SYSTEM "chkpass.sgml">
  <!entity citext          SYSTEM "citext.sgml">
diff -cprN HEAD/src/backend/commands/explain.c auto-explain/src/backend/commands/explain.c
*** HEAD/src/backend/commands/explain.c	Tue Oct  7 05:29:38 2008
--- auto-explain/src/backend/commands/explain.c	Mon Nov 10 17:55:49 2008
*************** ExplainOnePlan(PlannedStmt *plannedstmt,
*** 224,230 ****
  	QueryDesc  *queryDesc;
  	instr_time	starttime;
  	double		totaltime = 0;
- 	ExplainState *es;
  	StringInfoData buf;
  	int			eflags;
  
--- 224,229 ----
*************** ExplainOnePlan(PlannedStmt *plannedstmt,
*** 265,281 ****
  		totaltime += elapsed_time(&starttime);
  	}
  
- 	es = (ExplainState *) palloc0(sizeof(ExplainState));
- 
- 	es->printTList = stmt->verbose;
- 	es->printAnalyze = stmt->analyze;
- 	es->pstmt = queryDesc->plannedstmt;
- 	es->rtable = queryDesc->plannedstmt->rtable;
- 
  	initStringInfo(&buf);
! 	explain_outNode(&buf,
! 					queryDesc->plannedstmt->planTree, queryDesc->planstate,
! 					NULL, 0, es);
  
  	/*
  	 * If we ran the command, run any AFTER triggers it queued.  (Note this
--- 264,271 ----
  		totaltime += elapsed_time(&starttime);
  	}
  
  	initStringInfo(&buf);
! 	ExplainOneResult(&buf, queryDesc, stmt->analyze, stmt->verbose);
  
  	/*
  	 * If we ran the command, run any AFTER triggers it queued.  (Note this
*************** ExplainOnePlan(PlannedStmt *plannedstmt,
*** 290,296 ****
  	}
  
  	/* Print info about runtime of triggers */
! 	if (es->printAnalyze)
  	{
  		ResultRelInfo *rInfo;
  		bool		show_relname;
--- 280,286 ----
  	}
  
  	/* Print info about runtime of triggers */
! 	if (stmt->analyze)
  	{
  		ResultRelInfo *rInfo;
  		bool		show_relname;
*************** ExplainOnePlan(PlannedStmt *plannedstmt,
*** 335,341 ****
  	do_text_output_multiline(tstate, buf.data);
  
  	pfree(buf.data);
! 	pfree(es);
  }
  
  /*
--- 325,350 ----
  	do_text_output_multiline(tstate, buf.data);
  
  	pfree(buf.data);
! }
! 
! /*
!  * ExplainOneResult -
!  *	  converts a Plan node into ascii string and appends it to 'str'
!  */
! void
! ExplainOneResult(StringInfo str, QueryDesc *queryDesc,
! 				 bool analyze, bool verbose)
! {
! 	ExplainState	es = { 0 };
! 
! 	es.printTList = verbose;
! 	es.printAnalyze = analyze;
! 	es.pstmt = queryDesc->plannedstmt;
! 	es.rtable = queryDesc->plannedstmt->rtable;
! 
! 	explain_outNode(str,
! 					queryDesc->plannedstmt->planTree, queryDesc->planstate,
! 					NULL, 0, &es);
  }
  
  /*
diff -cprN HEAD/src/backend/tcop/pquery.c auto-explain/src/backend/tcop/pquery.c
*** HEAD/src/backend/tcop/pquery.c	Fri Aug  1 22:16:09 2008
--- auto-explain/src/backend/tcop/pquery.c	Mon Nov 10 17:55:49 2008
***************
*** 32,38 ****
   * if there are several).
   */
  Portal		ActivePortal = NULL;
! 
  
  static void ProcessQuery(PlannedStmt *plan,
  			 ParamListInfo params,
--- 32,38 ----
   * if there are several).
   */
  Portal		ActivePortal = NULL;
! bool		force_instrument = false;
  
  static void ProcessQuery(PlannedStmt *plan,
  			 ParamListInfo params,
*************** CreateQueryDesc(PlannedStmt *plannedstmt
*** 76,82 ****
  	qd->crosscheck_snapshot = RegisterSnapshot(crosscheck_snapshot);
  	qd->dest = dest;			/* output dest */
  	qd->params = params;		/* parameter values passed into query */
! 	qd->doInstrument = doInstrument;	/* instrumentation wanted? */
  
  	/* null these fields until set by ExecutorStart */
  	qd->tupDesc = NULL;
--- 76,82 ----
  	qd->crosscheck_snapshot = RegisterSnapshot(crosscheck_snapshot);
  	qd->dest = dest;			/* output dest */
  	qd->params = params;		/* parameter values passed into query */
! 	qd->doInstrument = force_instrument || doInstrument;	/* instrumentation wanted? */
  
  	/* null these fields until set by ExecutorStart */
  	qd->tupDesc = NULL;
diff -cprN HEAD/src/backend/utils/misc/guc.c auto-explain/src/backend/utils/misc/guc.c
*** HEAD/src/backend/utils/misc/guc.c	Sun Nov  9 09:28:35 2008
--- auto-explain/src/backend/utils/misc/guc.c	Mon Nov 10 17:55:49 2008
*************** static const char *assign_pgstat_temp_di
*** 169,174 ****
--- 169,175 ----
  
  static char *config_enum_get_options(struct config_enum *record, 
  									 const char *prefix, const char *suffix);
+ static void initialize_option(struct config_generic *gconf);
  
  
  /*
*************** InitializeGUCOptions(void)
*** 3194,3305 ****
  	for (i = 0; i < num_guc_variables; i++)
  	{
  		struct config_generic *gconf = guc_variables[i];
! 
! 		gconf->status = 0;
! 		gconf->reset_source = PGC_S_DEFAULT;
! 		gconf->source = PGC_S_DEFAULT;
! 		gconf->stack = NULL;
! 		gconf->sourcefile = NULL;
! 		gconf->sourceline = 0;
! 
! 		switch (gconf->vartype)
! 		{
! 			case PGC_BOOL:
! 				{
! 					struct config_bool *conf = (struct config_bool *) gconf;
! 
! 					if (conf->assign_hook)
! 						if (!(*conf->assign_hook) (conf->boot_val, true,
! 												   PGC_S_DEFAULT))
! 							elog(FATAL, "failed to initialize %s to %d",
! 								 conf->gen.name, (int) conf->boot_val);
! 					*conf->variable = conf->reset_val = conf->boot_val;
! 					break;
! 				}
! 			case PGC_INT:
! 				{
! 					struct config_int *conf = (struct config_int *) gconf;
! 
! 					Assert(conf->boot_val >= conf->min);
! 					Assert(conf->boot_val <= conf->max);
! 					if (conf->assign_hook)
! 						if (!(*conf->assign_hook) (conf->boot_val, true,
! 												   PGC_S_DEFAULT))
! 							elog(FATAL, "failed to initialize %s to %d",
! 								 conf->gen.name, conf->boot_val);
! 					*conf->variable = conf->reset_val = conf->boot_val;
! 					break;
! 				}
! 			case PGC_REAL:
! 				{
! 					struct config_real *conf = (struct config_real *) gconf;
! 
! 					Assert(conf->boot_val >= conf->min);
! 					Assert(conf->boot_val <= conf->max);
! 					if (conf->assign_hook)
! 						if (!(*conf->assign_hook) (conf->boot_val, true,
! 												   PGC_S_DEFAULT))
! 							elog(FATAL, "failed to initialize %s to %g",
! 								 conf->gen.name, conf->boot_val);
! 					*conf->variable = conf->reset_val = conf->boot_val;
! 					break;
! 				}
! 			case PGC_STRING:
! 				{
! 					struct config_string *conf = (struct config_string *) gconf;
! 					char	   *str;
! 
! 					*conf->variable = NULL;
! 					conf->reset_val = NULL;
! 
! 					if (conf->boot_val == NULL)
! 					{
! 						/* leave the value NULL, do not call assign hook */
! 						break;
! 					}
! 
! 					str = guc_strdup(FATAL, conf->boot_val);
! 					conf->reset_val = str;
! 
! 					if (conf->assign_hook)
! 					{
! 						const char *newstr;
! 
! 						newstr = (*conf->assign_hook) (str, true,
! 													   PGC_S_DEFAULT);
! 						if (newstr == NULL)
! 						{
! 							elog(FATAL, "failed to initialize %s to \"%s\"",
! 								 conf->gen.name, str);
! 						}
! 						else if (newstr != str)
! 						{
! 							free(str);
! 
! 							/*
! 							 * See notes in set_config_option about casting
! 							 */
! 							str = (char *) newstr;
! 							conf->reset_val = str;
! 						}
! 					}
! 					*conf->variable = str;
! 					break;
! 				}
! 			case PGC_ENUM:
! 				{
! 					struct config_enum *conf = (struct config_enum *) gconf;
! 
! 					if (conf->assign_hook)
! 						if (!(*conf->assign_hook) (conf->boot_val, true,
! 												   PGC_S_DEFAULT))
! 							elog(FATAL, "failed to initialize %s to %s",
! 								 conf->gen.name, 
! 								 config_enum_lookup_by_value(conf, conf->boot_val));
! 					*conf->variable = conf->reset_val = conf->boot_val;
! 					break;
! 				}
! 		}
  	}
  
  	guc_dirty = false;
--- 3195,3201 ----
  	for (i = 0; i < num_guc_variables; i++)
  	{
  		struct config_generic *gconf = guc_variables[i];
! 		initialize_option(gconf);
  	}
  
  	guc_dirty = false;
*************** InitializeGUCOptions(void)
*** 3355,3360 ****
--- 3251,3365 ----
  	}
  }
  
+ static void
+ initialize_option(struct config_generic *gconf)
+ {
+ 	gconf->status = 0;
+ 	gconf->reset_source = PGC_S_DEFAULT;
+ 	gconf->source = PGC_S_DEFAULT;
+ 	gconf->stack = NULL;
+ 	gconf->sourcefile = NULL;
+ 	gconf->sourceline = 0;
+ 
+ 	switch (gconf->vartype)
+ 	{
+ 		case PGC_BOOL:
+ 			{
+ 				struct config_bool *conf = (struct config_bool *) gconf;
+ 
+ 				if (conf->assign_hook)
+ 					if (!(*conf->assign_hook) (conf->boot_val, true,
+ 											   PGC_S_DEFAULT))
+ 						elog(FATAL, "failed to initialize %s to %d",
+ 							 conf->gen.name, (int) conf->boot_val);
+ 				*conf->variable = conf->reset_val = conf->boot_val;
+ 				break;
+ 			}
+ 		case PGC_INT:
+ 			{
+ 				struct config_int *conf = (struct config_int *) gconf;
+ 
+ 				Assert(conf->boot_val >= conf->min);
+ 				Assert(conf->boot_val <= conf->max);
+ 				if (conf->assign_hook)
+ 					if (!(*conf->assign_hook) (conf->boot_val, true,
+ 											   PGC_S_DEFAULT))
+ 						elog(FATAL, "failed to initialize %s to %d",
+ 							 conf->gen.name, conf->boot_val);
+ 				*conf->variable = conf->reset_val = conf->boot_val;
+ 				break;
+ 			}
+ 		case PGC_REAL:
+ 			{
+ 				struct config_real *conf = (struct config_real *) gconf;
+ 
+ 				Assert(conf->boot_val >= conf->min);
+ 				Assert(conf->boot_val <= conf->max);
+ 				if (conf->assign_hook)
+ 					if (!(*conf->assign_hook) (conf->boot_val, true,
+ 											   PGC_S_DEFAULT))
+ 						elog(FATAL, "failed to initialize %s to %g",
+ 							 conf->gen.name, conf->boot_val);
+ 				*conf->variable = conf->reset_val = conf->boot_val;
+ 				break;
+ 			}
+ 		case PGC_STRING:
+ 			{
+ 				struct config_string *conf = (struct config_string *) gconf;
+ 				char	   *str;
+ 
+ 				*conf->variable = NULL;
+ 				conf->reset_val = NULL;
+ 
+ 				if (conf->boot_val == NULL)
+ 				{
+ 					/* leave the value NULL, do not call assign hook */
+ 					break;
+ 				}
+ 
+ 				str = guc_strdup(FATAL, conf->boot_val);
+ 				conf->reset_val = str;
+ 
+ 				if (conf->assign_hook)
+ 				{
+ 					const char *newstr;
+ 
+ 					newstr = (*conf->assign_hook) (str, true,
+ 												   PGC_S_DEFAULT);
+ 					if (newstr == NULL)
+ 					{
+ 						elog(FATAL, "failed to initialize %s to \"%s\"",
+ 							 conf->gen.name, str);
+ 					}
+ 					else if (newstr != str)
+ 					{
+ 						free(str);
+ 
+ 						/*
+ 						 * See notes in set_config_option about casting
+ 						 */
+ 						str = (char *) newstr;
+ 						conf->reset_val = str;
+ 					}
+ 				}
+ 				*conf->variable = str;
+ 				break;
+ 			}
+ 		case PGC_ENUM:
+ 			{
+ 				struct config_enum *conf = (struct config_enum *) gconf;
+ 
+ 				if (conf->assign_hook)
+ 					if (!(*conf->assign_hook) (conf->boot_val, true,
+ 											   PGC_S_DEFAULT))
+ 						elog(FATAL, "failed to initialize %s to %s",
+ 							 conf->gen.name, 
+ 							 config_enum_lookup_by_value(conf, conf->boot_val));
+ 				*conf->variable = conf->reset_val = conf->boot_val;
+ 				break;
+ 			}
+ 	}
+ }
  
  /*
   * Select the configuration files and data directory to be used, and
*************** define_custom_variable(struct config_gen
*** 5656,5661 ****
--- 5661,5667 ----
  	if (res == NULL)
  	{
  		/* No placeholder to replace, so just add it */
+ 		initialize_option(variable);
  		add_guc_variable(variable, ERROR);
  		return;
  	}
*************** define_custom_variable(struct config_gen
*** 5690,5695 ****
--- 5696,5703 ----
  		set_config_option(name, value,
  						  pHolder->gen.context, pHolder->gen.source,
  						  GUC_ACTION_SET, true);
+ 	else
+ 		initialize_option(variable);
  
  	/*
  	 * Free up as much as we conveniently can of the placeholder structure
*************** DefineCustomEnumVariable(const char *nam
*** 5821,5826 ****
--- 5829,5857 ----
  	var->assign_hook = assign_hook;
  	var->show_hook = show_hook;
  	define_custom_variable(&var->gen);
+ }
+ 
+ static const int config_varsize[] =
+ {
+ 	sizeof(struct config_bool),
+ 	sizeof(struct config_int),
+ 	sizeof(struct config_real),
+ 	sizeof(struct config_string),
+ 	sizeof(struct config_enum),
+ };
+ 
+ void
+ DefineCustomVariable(enum config_type type, const void *variable)
+ {
+ 	int		size = config_varsize[type];
+ 	const struct config_generic	   *var = variable;
+ 	struct config_generic		   *gen;
+ 
+ 	gen = (struct config_generic *) guc_malloc(ERROR, size);
+ 	memcpy(gen, var, size);
+ 	gen->name = guc_strdup(ERROR, var->name);
+ 	gen->vartype = type;
+ 	define_custom_variable(gen);
  }
  
  void
diff -cprN HEAD/src/include/commands/explain.h auto-explain/src/include/commands/explain.h
*** HEAD/src/include/commands/explain.h	Wed Jan  2 04:45:57 2008
--- auto-explain/src/include/commands/explain.h	Mon Nov 10 17:55:49 2008
*************** extern void ExplainOneUtility(Node *util
*** 41,44 ****
--- 41,47 ----
  extern void ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
  			   ExplainStmt *stmt, TupOutputState *tstate);
  
+ extern void ExplainOneResult(StringInfo str, QueryDesc *queryDesc,
+ 							 bool analyze, bool verbose);
+ 
  #endif   /* EXPLAIN_H */
diff -cprN HEAD/src/include/executor/execdesc.h auto-explain/src/include/executor/execdesc.h
*** HEAD/src/include/executor/execdesc.h	Wed Jan  2 04:45:57 2008
--- auto-explain/src/include/executor/execdesc.h	Mon Nov 10 17:55:49 2008
***************
*** 20,25 ****
--- 20,27 ----
  #include "tcop/dest.h"
  
  
+ extern PGDLLIMPORT bool force_instrument;
+ 
  /* ----------------
   *		query descriptor:
   *
diff -cprN HEAD/src/include/utils/guc_tables.h auto-explain/src/include/utils/guc_tables.h
*** HEAD/src/include/utils/guc_tables.h	Tue Sep 30 19:52:14 2008
--- auto-explain/src/include/utils/guc_tables.h	Mon Nov 10 17:55:49 2008
*************** extern const char *config_enum_lookup_by
*** 242,246 ****
--- 242,247 ----
  extern bool config_enum_lookup_by_name(struct config_enum *record,
  									  const char *value, int *retval);
  
+ extern void DefineCustomVariable(enum config_type type, const void *variable);
  
  #endif   /* GUC_TABLES_H */

diff --git a/contrib/Makefile b/contrib/Makefile
index 30f75c7..b25af3c 100644
--- a/contrib/Makefile
+++ b/contrib/Makefile
@@ -6,6 +6,7 @@ include $(top_builddir)/src/Makefile.global
 
 WANTED_DIRS = \
 		adminpack	\
+		auto_explain	\
 		btree_gist	\
 		chkpass		\
 		citext		\
diff --git a/contrib/auto_explain/Makefile b/contrib/auto_explain/Makefile
new file mode 100644
index 0000000..0d0ccc2
--- /dev/null
+++ b/contrib/auto_explain/Makefile
@@ -0,0 +1,13 @@
+MODULE_big = auto_explain
+OBJS = auto_explain.o
+
+ifdef USE_PGXS
+PG_CONFIG = pg_config
+PGXS := $(shell $(PG_CONFIG) --pgxs)
+include $(PGXS)
+else
+subdir = contrib/auto_explain
+top_builddir = ../..
+include $(top_builddir)/src/Makefile.global
+include $(top_srcdir)/contrib/contrib-global.mk
+endif
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
new file mode 100644
index 0000000..af994e7
--- /dev/null
+++ b/contrib/auto_explain/auto_explain.c
@@ -0,0 +1,215 @@
+/*
+ * auto_explain.c
+ */
+#include "postgres.h"
+
+#include "commands/explain.h"
+#include "executor/instrument.h"
+#include "miscadmin.h"
+#include "utils/guc_tables.h"
+
+PG_MODULE_MAGIC;
+
+#define GUCNAME(name)		("explain." name)
+
+static int		explain_log_min_duration = -1;	/* msec or -1 */
+static bool		explain_log_analyze = false;
+static bool		explain_log_verbose = false;
+static bool		explain_log_nested = false;
+
+static bool		toplevel = true;
+static ExecutorRun_hook_type	prev_ExecutorRun = NULL;
+
+void	_PG_init(void);
+void	_PG_fini(void);
+
+static void explain_ExecutorRun(QueryDesc *queryDesc,
+								ScanDirection direction,
+								long count);
+static bool assign_log_min_duration(int newval, bool doit, GucSource source);
+static bool assign_log_analyze(bool newval, bool doit, GucSource source);
+static bool assign_log_verbose(bool newval, bool doit, GucSource source);
+static bool assign_log_nested(bool newval, bool doit, GucSource source);
+
+static struct config_int def_log_min_duration =
+{
+	{
+		GUCNAME("log_min_duration"),
+		PGC_USERSET,
+		STATS_MONITORING,
+		"Sets the minimum execution time above which plans will be logged.",
+		"Zero prints all plans. -1 turns this feature off.",
+		GUC_UNIT_MS
+	},
+	&explain_log_min_duration,
+	-1, -1, INT_MAX / 1000, assign_log_min_duration, NULL
+};
+
+static struct config_bool def_log_analyze =
+{
+	{
+		GUCNAME("log_analyze"),
+		PGC_USERSET,
+		STATS_MONITORING,
+		"Use EXPLAIN ANALYZE for plan logging."
+	},
+	&explain_log_analyze,
+	false, assign_log_analyze, NULL
+};
+
+static struct config_bool def_log_verbose =
+{
+	{
+		GUCNAME("log_verbose"),
+		PGC_USERSET,
+		STATS_MONITORING,
+		"Use EXPLAIN VERBOSE for plan logging."
+	},
+	&explain_log_verbose,
+	false, assign_log_verbose, NULL
+};
+
+static struct config_bool def_log_nested_statements =
+{
+	{
+		GUCNAME("log_nested_statements"),
+		PGC_USERSET,
+		STATS_MONITORING,
+		"Log nested statements."
+	},
+	&explain_log_nested,
+	false, assign_log_nested, NULL
+};
+
+void
+_PG_init(void)
+{
+	DefineCustomVariable(PGC_INT, &def_log_min_duration);
+	DefineCustomVariable(PGC_BOOL, &def_log_analyze);
+	DefineCustomVariable(PGC_BOOL, &def_log_verbose);
+	DefineCustomVariable(PGC_BOOL, &def_log_nested_statements);
+
+	/* install ExecutorRun_hook */
+	prev_ExecutorRun = ExecutorRun_hook;
+	ExecutorRun_hook = explain_ExecutorRun;
+}
+
+void
+_PG_fini(void)
+{
+	/* uninstall ExecutorRun_hook */
+	ExecutorRun_hook = prev_ExecutorRun;
+}
+
+void
+explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, long count)
+{
+	if ((toplevel || explain_log_nested) && explain_log_min_duration >= 0)
+	{
+		instr_time		starttime;
+		instr_time		duration;
+		double			msec;
+
+		/* Disable our hooks temporarily during the top-level query. */
+		toplevel = false;
+		PG_TRY();
+		{
+			INSTR_TIME_SET_CURRENT(starttime);
+
+			if (prev_ExecutorRun)
+				prev_ExecutorRun(queryDesc, direction, count);
+			else
+				standard_ExecutorRun(queryDesc, direction, count);
+
+			INSTR_TIME_SET_CURRENT(duration);
+			INSTR_TIME_SUBTRACT(duration, starttime);
+			msec = INSTR_TIME_GET_MILLISEC(duration);
+
+			/* Log plan if duration is exceeded. */
+			if (msec > explain_log_min_duration)
+			{
+				StringInfoData	buf;
+
+				initStringInfo(&buf);
+				ExplainOneResult(&buf, queryDesc,
+					queryDesc->doInstrument && explain_log_analyze,
+					explain_log_verbose);
+
+				/* Remove last line break */
+				if (buf.len > 0 && buf.data[buf.len - 1] == '\n')
+				{
+					buf.data[buf.len - 1] = '\0';
+					buf.len--;
+				}
+				ereport(LOG,
+						(errmsg("duration: %.3f ms  plan:\n%s",
+								msec, buf.data)));
+
+				pfree(buf.data);
+			}
+
+			toplevel = true;
+		}
+		PG_CATCH();
+		{
+			toplevel = true;
+			PG_RE_THROW();
+		}
+		PG_END_TRY();
+	}
+	else
+	{
+		/* ignore recursive executions, that are typically function calls */
+		if (prev_ExecutorRun)
+			prev_ExecutorRun(queryDesc, direction, count);
+		else
+			standard_ExecutorRun(queryDesc, direction, count);
+	}
+}
+
+/* Emulate PGC_SUSET for custom variables. */
+static bool
+suset_assign(GucSource source, const char *name)
+{
+	if (source >= PGC_S_CLIENT && !superuser())
+	{
+		ereport(GUC_complaint_elevel(source),
+				(errcode(ERRCODE_INSUFFICIENT_PRIVILEGE),
+				 errmsg("permission denied to set parameter \"%s\"", name)));
+		return false;
+	}
+
+	return true;
+}
+
+static bool
+assign_log_min_duration(int newval, bool doit, GucSource source)
+{
+	if (!suset_assign(source, GUCNAME("log_min_duration")))
+		return false;
+	if (doit)
+		force_instrument = (newval >= 0 && explain_log_analyze);
+	return true;
+}
+
+static bool
+assign_log_analyze(bool newval, bool doit, GucSource source)
+{
+	if (!suset_assign(source, GUCNAME("log_analyze")))
+		return false;
+	if (doit)
+		force_instrument = (explain_log_min_duration >= 0 && newval);
+	return true;
+}
+
+static bool
+assign_log_verbose(bool newval, bool doit, GucSource source)
+{
+	return suset_assign(source, GUCNAME("log_verbose"));
+}
+
+static bool
+assign_log_nested(bool newval, bool doit, GucSource source)
+{
+	return suset_assign(source, GUCNAME("log_nested_statements"));
+}
diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml
new file mode 100644
index 0000000..94b7daf
--- /dev/null
+++ b/doc/src/sgml/auto-explain.sgml
@@ -0,0 +1,141 @@
+<sect1 id="autoexplain">
+ <title>auto_explain</title>
+
+ <indexterm zone="autoexplain">
+  <primary>auto_explain</primary>
+ </indexterm>
+
+ <para>
+  The <filename>auto_explain</filename> module provides a means for
+  logging execution plans automatically, without having to run <command>EXPLAIN</>.
+ </para>
+
+ <para>
+  You can <command>LOAD</> this module dynamically or preload it automatically with
+  <varname>shared_preload_libraries</> or <varname>local_preload_libraries</>.
+ </para>
+
+ <sect2>
+  <title>Configuration parameters</title>
+
+  <variablelist>
+   <varlistentry>
+    <term>
+     <varname>explain.log_min_duration</varname> (<type>integer</type>)
+    </term>
+    <listitem>
+     <para>
+      <varname>explain.log_min_duration</varname> is the minimum execution time
+      in milliseconds that will cause the plan to be logged. Setting this to zero
+      logs all plans. Minus-one (the default) disables logging of plans.
+      For example, if you set it to <literal>250ms</literal> then all plans
+      that run 250ms or longer in executor will be logged.
+      Enabling this parameter can be helpful in tracking down unoptimized queries
+      in your applications. Only superusers can change this setting.
+     </para>
+    </listitem>
+   </varlistentry>
+
+   <varlistentry>
+    <term>
+     <varname>explain.log_analyze</varname> (<type>boolean</type>)
+    </term>
+
+    <listitem>
+     <para>
+      <varname>explain.log_analyze</varname> causes <command>EXPLAIN ANALYZE</>
+      to be used rather than normal <command>EXPLAIN</> when an execution plan
+      is logged. This parameter is off by default. Only superusers can change
+      this setting.
+     </para>
+     <para>
+      NOTE: If you set the parameter on, instrument timers are enabled even if
+      you don't use EXPLAIN ANALYZE. This creates some overhead for all
+      statements executed.
+     </para>
+    </listitem>
+   </varlistentry>
+
+   <varlistentry>
+    <term>
+     <varname>explain.log_verbose</varname> (<type>boolean</type>)
+    </term>
+
+    <listitem>
+     <para>
+      <varname>explain.log_verbose</varname> causes <command>EXPLAIN VERBOSE</>
+      to be used rather than normal <command>EXPLAIN</> when an execution plan
+      is logged. This parameter is off by default. Only superusers can change
+      this setting.
+     </para>
+    </listitem>
+   </varlistentry>
+
+   <varlistentry>
+    <term>
+     <varname>explain.log_nested_statements</varname> (<type>boolean</type>)
+    </term>
+
+    <listitem>
+     <para>
+      <varname>explain.log_nested_statements</varname> causes the execution plans
+      of nested statements (statements executed inside a function) to be logged
+      as well. If the value is off, only top-level plans are logged. This
+      parameter is off by default. Only superusers can change this setting.
+     </para>
+    </listitem>
+   </varlistentry>
+  </variablelist>
+
+  <para>
+   If you set these explain.* parameters in your postgresql.conf,
+   you also need to add 'explain' in <varname>custom_variable_classes</>.
+  </para>
+
+  <programlisting>
+  # postgresql.conf
+  shared_preload_libraries = 'auto_explain'
+  
+  custom_variable_classes = 'explain'
+  explain.log_min_duration = 3s
+  </programlisting>
+ </sect2>
+
+ <sect2>
+  <title>Example</title>
+
+  <programlisting>
+  postgres=# LOAD 'auto_explain';
+  postgres=# SET explain.log_min_duration = 0;
+  postgres=# SELECT count(*)
+               FROM pg_class, pg_index
+              WHERE oid = indrelid AND indisunique;
+  </programlisting>
+ </sect2>
+
+ <sect2>
+  <title>Sample Log Output</title>
+  <programlisting>
+  LOG:  duration: 0.986 ms  plan:
+          Aggregate  (cost=14.90..14.91 rows=1 width=0)
+            ->  Hash Join  (cost=3.91..14.70 rows=81 width=0)
+                  Hash Cond: (pg_class.oid = pg_index.indrelid)
+                  ->  Seq Scan on pg_class  (cost=0.00..8.27 rows=227 width=4)
+                  ->  Hash  (cost=2.90..2.90 rows=81 width=4)
+                        ->  Seq Scan on pg_index  (cost=0.00..2.90 rows=81 width=4)
+                              Filter: indisunique
+  STATEMENT:  SELECT count(*)
+            FROM pg_class, pg_index
+           WHERE oid = indrelid AND indisunique;
+  </programlisting>
+ </sect2>
+
+ <sect2>
+  <title>Authors</title>
+
+  <para>
+   Takahiro Itagaki <email>itagaki.takahiro@oss.ntt.co.jp</email>
+  </para>
+ </sect2>
+
+</sect1>
diff --git a/doc/src/sgml/contrib.sgml b/doc/src/sgml/contrib.sgml
index 72d8828..0108da3 100644
--- a/doc/src/sgml/contrib.sgml
+++ b/doc/src/sgml/contrib.sgml
@@ -79,6 +79,7 @@ psql -d dbname -f <replaceable>SHAREDIR</>/contrib/<replaceable>module</>.sql
  </para>
 
  &adminpack;
+ &auto-explain;
  &btree-gist;
  &chkpass;
  &citext;
diff --git a/doc/src/sgml/filelist.sgml b/doc/src/sgml/filelist.sgml
index b0538b6..68db2b9 100644
--- a/doc/src/sgml/filelist.sgml
+++ b/doc/src/sgml/filelist.sgml
@@ -92,6 +92,7 @@
 <!-- contrib information -->
 <!entity contrib         SYSTEM "contrib.sgml">
 <!entity adminpack       SYSTEM "adminpack.sgml">
+<!entity auto-explain    SYSTEM "auto-explain.sgml">
 <!entity btree-gist      SYSTEM "btree-gist.sgml">
 <!entity chkpass         SYSTEM "chkpass.sgml">
 <!entity citext          SYSTEM "citext.sgml">
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index c0c53cf..4d46a34 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -224,7 +224,6 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
 	QueryDesc  *queryDesc;
 	instr_time	starttime;
 	double		totaltime = 0;
-	ExplainState *es;
 	StringInfoData buf;
 	int			eflags;
 
@@ -265,17 +264,8 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
 		totaltime += elapsed_time(&starttime);
 	}
 
-	es = (ExplainState *) palloc0(sizeof(ExplainState));
-
-	es->printTList = stmt->verbose;
-	es->printAnalyze = stmt->analyze;
-	es->pstmt = queryDesc->plannedstmt;
-	es->rtable = queryDesc->plannedstmt->rtable;
-
 	initStringInfo(&buf);
-	explain_outNode(&buf,
-					queryDesc->plannedstmt->planTree, queryDesc->planstate,
-					NULL, 0, es);
+	ExplainOneResult(&buf, queryDesc, stmt->analyze, stmt->verbose);
 
 	/*
 	 * If we ran the command, run any AFTER triggers it queued.  (Note this
@@ -290,7 +280,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
 	}
 
 	/* Print info about runtime of triggers */
-	if (es->printAnalyze)
+	if (stmt->analyze)
 	{
 		ResultRelInfo *rInfo;
 		bool		show_relname;
@@ -335,7 +325,26 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
 	do_text_output_multiline(tstate, buf.data);
 
 	pfree(buf.data);
-	pfree(es);
+}
+
+/*
+ * ExplainOneResult -
+ *	  converts a Plan node into ascii string and appends it to 'str'
+ */
+void
+ExplainOneResult(StringInfo str, QueryDesc *queryDesc,
+				 bool analyze, bool verbose)
+{
+	ExplainState	es = { 0 };
+
+	es.printTList = verbose;
+	es.printAnalyze = analyze;
+	es.pstmt = queryDesc->plannedstmt;
+	es.rtable = queryDesc->plannedstmt->rtable;
+
+	explain_outNode(str,
+					queryDesc->plannedstmt->planTree, queryDesc->planstate,
+					NULL, 0, &es);
 }
 
 /*
diff --git a/src/backend/tcop/pquery.c b/src/backend/tcop/pquery.c
index a933d3c..ff2df9b 100644
--- a/src/backend/tcop/pquery.c
+++ b/src/backend/tcop/pquery.c
@@ -32,7 +32,7 @@
  * if there are several).
  */
 Portal		ActivePortal = NULL;
-
+bool		force_instrument = false;
 
 static void ProcessQuery(PlannedStmt *plan,
 			 ParamListInfo params,
@@ -76,7 +76,7 @@ CreateQueryDesc(PlannedStmt *plannedstmt,
 	qd->crosscheck_snapshot = RegisterSnapshot(crosscheck_snapshot);
 	qd->dest = dest;			/* output dest */
 	qd->params = params;		/* parameter values passed into query */
-	qd->doInstrument = doInstrument;	/* instrumentation wanted? */
+	qd->doInstrument = force_instrument || doInstrument;	/* instrumentation wanted? */
 
 	/* null these fields until set by ExecutorStart */
 	qd->tupDesc = NULL;
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index fd7543b..f8a7e64 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -169,6 +169,7 @@ static const char *assign_pgstat_temp_directory(const char *newval, bool doit, G
 
 static char *config_enum_get_options(struct config_enum *record, 
 									 const char *prefix, const char *suffix);
+static void initialize_option(struct config_generic *gconf);
 
 
 /*
@@ -3194,112 +3195,7 @@ InitializeGUCOptions(void)
 	for (i = 0; i < num_guc_variables; i++)
 	{
 		struct config_generic *gconf = guc_variables[i];
-
-		gconf->status = 0;
-		gconf->reset_source = PGC_S_DEFAULT;
-		gconf->source = PGC_S_DEFAULT;
-		gconf->stack = NULL;
-		gconf->sourcefile = NULL;
-		gconf->sourceline = 0;
-
-		switch (gconf->vartype)
-		{
-			case PGC_BOOL:
-				{
-					struct config_bool *conf = (struct config_bool *) gconf;
-
-					if (conf->assign_hook)
-						if (!(*conf->assign_hook) (conf->boot_val, true,
-												   PGC_S_DEFAULT))
-							elog(FATAL, "failed to initialize %s to %d",
-								 conf->gen.name, (int) conf->boot_val);
-					*conf->variable = conf->reset_val = conf->boot_val;
-					break;
-				}
-			case PGC_INT:
-				{
-					struct config_int *conf = (struct config_int *) gconf;
-
-					Assert(conf->boot_val >= conf->min);
-					Assert(conf->boot_val <= conf->max);
-					if (conf->assign_hook)
-						if (!(*conf->assign_hook) (conf->boot_val, true,
-												   PGC_S_DEFAULT))
-							elog(FATAL, "failed to initialize %s to %d",
-								 conf->gen.name, conf->boot_val);
-					*conf->variable = conf->reset_val = conf->boot_val;
-					break;
-				}
-			case PGC_REAL:
-				{
-					struct config_real *conf = (struct config_real *) gconf;
-
-					Assert(conf->boot_val >= conf->min);
-					Assert(conf->boot_val <= conf->max);
-					if (conf->assign_hook)
-						if (!(*conf->assign_hook) (conf->boot_val, true,
-												   PGC_S_DEFAULT))
-							elog(FATAL, "failed to initialize %s to %g",
-								 conf->gen.name, conf->boot_val);
-					*conf->variable = conf->reset_val = conf->boot_val;
-					break;
-				}
-			case PGC_STRING:
-				{
-					struct config_string *conf = (struct config_string *) gconf;
-					char	   *str;
-
-					*conf->variable = NULL;
-					conf->reset_val = NULL;
-
-					if (conf->boot_val == NULL)
-					{
-						/* leave the value NULL, do not call assign hook */
-						break;
-					}
-
-					str = guc_strdup(FATAL, conf->boot_val);
-					conf->reset_val = str;
-
-					if (conf->assign_hook)
-					{
-						const char *newstr;
-
-						newstr = (*conf->assign_hook) (str, true,
-													   PGC_S_DEFAULT);
-						if (newstr == NULL)
-						{
-							elog(FATAL, "failed to initialize %s to \"%s\"",
-								 conf->gen.name, str);
-						}
-						else if (newstr != str)
-						{
-							free(str);
-
-							/*
-							 * See notes in set_config_option about casting
-							 */
-							str = (char *) newstr;
-							conf->reset_val = str;
-						}
-					}
-					*conf->variable = str;
-					break;
-				}
-			case PGC_ENUM:
-				{
-					struct config_enum *conf = (struct config_enum *) gconf;
-
-					if (conf->assign_hook)
-						if (!(*conf->assign_hook) (conf->boot_val, true,
-												   PGC_S_DEFAULT))
-							elog(FATAL, "failed to initialize %s to %s",
-								 conf->gen.name, 
-								 config_enum_lookup_by_value(conf, conf->boot_val));
-					*conf->variable = conf->reset_val = conf->boot_val;
-					break;
-				}
-		}
+		initialize_option(gconf);
 	}
 
 	guc_dirty = false;
@@ -3355,6 +3251,115 @@ InitializeGUCOptions(void)
 	}
 }
 
+static void
+initialize_option(struct config_generic *gconf)
+{
+	gconf->status = 0;
+	gconf->reset_source = PGC_S_DEFAULT;
+	gconf->source = PGC_S_DEFAULT;
+	gconf->stack = NULL;
+	gconf->sourcefile = NULL;
+	gconf->sourceline = 0;
+
+	switch (gconf->vartype)
+	{
+		case PGC_BOOL:
+			{
+				struct config_bool *conf = (struct config_bool *) gconf;
+
+				if (conf->assign_hook)
+					if (!(*conf->assign_hook) (conf->boot_val, true,
+											   PGC_S_DEFAULT))
+						elog(FATAL, "failed to initialize %s to %d",
+							 conf->gen.name, (int) conf->boot_val);
+				*conf->variable = conf->reset_val = conf->boot_val;
+				break;
+			}
+		case PGC_INT:
+			{
+				struct config_int *conf = (struct config_int *) gconf;
+
+				Assert(conf->boot_val >= conf->min);
+				Assert(conf->boot_val <= conf->max);
+				if (conf->assign_hook)
+					if (!(*conf->assign_hook) (conf->boot_val, true,
+											   PGC_S_DEFAULT))
+						elog(FATAL, "failed to initialize %s to %d",
+							 conf->gen.name, conf->boot_val);
+				*conf->variable = conf->reset_val = conf->boot_val;
+				break;
+			}
+		case PGC_REAL:
+			{
+				struct config_real *conf = (struct config_real *) gconf;
+
+				Assert(conf->boot_val >= conf->min);
+				Assert(conf->boot_val <= conf->max);
+				if (conf->assign_hook)
+					if (!(*conf->assign_hook) (conf->boot_val, true,
+											   PGC_S_DEFAULT))
+						elog(FATAL, "failed to initialize %s to %g",
+							 conf->gen.name, conf->boot_val);
+				*conf->variable = conf->reset_val = conf->boot_val;
+				break;
+			}
+		case PGC_STRING:
+			{
+				struct config_string *conf = (struct config_string *) gconf;
+				char	   *str;
+
+				*conf->variable = NULL;
+				conf->reset_val = NULL;
+
+				if (conf->boot_val == NULL)
+				{
+					/* leave the value NULL, do not call assign hook */
+					break;
+				}
+
+				str = guc_strdup(FATAL, conf->boot_val);
+				conf->reset_val = str;
+
+				if (conf->assign_hook)
+				{
+					const char *newstr;
+
+					newstr = (*conf->assign_hook) (str, true,
+												   PGC_S_DEFAULT);
+					if (newstr == NULL)
+					{
+						elog(FATAL, "failed to initialize %s to \"%s\"",
+							 conf->gen.name, str);
+					}
+					else if (newstr != str)
+					{
+						free(str);
+
+						/*
+						 * See notes in set_config_option about casting
+						 */
+						str = (char *) newstr;
+						conf->reset_val = str;
+					}
+				}
+				*conf->variable = str;
+				break;
+			}
+		case PGC_ENUM:
+			{
+				struct config_enum *conf = (struct config_enum *) gconf;
+
+				if (conf->assign_hook)
+					if (!(*conf->assign_hook) (conf->boot_val, true,
+											   PGC_S_DEFAULT))
+						elog(FATAL, "failed to initialize %s to %s",
+							 conf->gen.name, 
+							 config_enum_lookup_by_value(conf, conf->boot_val));
+				*conf->variable = conf->reset_val = conf->boot_val;
+				break;
+			}
+	}
+}
 
 /*
  * Select the configuration files and data directory to be used, and
@@ -5656,6 +5661,7 @@ define_custom_variable(struct config_generic * variable)
 	if (res == NULL)
 	{
 		/* No placeholder to replace, so just add it */
+		initialize_option(variable);
 		add_guc_variable(variable, ERROR);
 		return;
 	}
@@ -5690,6 +5696,8 @@ define_custom_variable(struct config_generic * variable)
 		set_config_option(name, value,
 						  pHolder->gen.context, pHolder->gen.source,
 						  GUC_ACTION_SET, true);
+	else
+		initialize_option(variable);
 
 	/*
 	 * Free up as much as we conveniently can of the placeholder structure
@@ -5823,6 +5831,29 @@ DefineCustomEnumVariable(const char *name,
 	define_custom_variable(&var->gen);
 }
 
+static const int config_varsize[] =
+{
+	sizeof(struct config_bool),
+	sizeof(struct config_int),
+	sizeof(struct config_real),
+	sizeof(struct config_string),
+	sizeof(struct config_enum),
+};
+
+void
+DefineCustomVariable(enum config_type type, const void *variable)
+{
+	int		size = config_varsize[type];
+	const struct config_generic	   *var = variable;
+	struct config_generic		   *gen;
+
+	gen = (struct config_generic *) guc_malloc(ERROR, size);
+	memcpy(gen, var, size);
+	gen->name = guc_strdup(ERROR, var->name);
+	gen->vartype = type;
+	define_custom_variable(gen);
+}
+
 void
 EmitWarningsOnPlaceholders(const char *className)
 {
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 5b808d5..cf07915 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -41,4 +41,7 @@ extern void ExplainOneUtility(Node *utilityStmt, ExplainStmt *stmt,
 extern void ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
 			   ExplainStmt *stmt, TupOutputState *tstate);
 
+extern void ExplainOneResult(StringInfo str, QueryDesc *queryDesc,
+							 bool analyze, bool verbose);
+
 #endif   /* EXPLAIN_H */
diff --git a/src/include/executor/execdesc.h b/src/include/executor/execdesc.h
index 2e2c159..854721c 100644
--- a/src/include/executor/execdesc.h
+++ b/src/include/executor/execdesc.h
@@ -20,6 +20,8 @@
 #include "tcop/dest.h"
 
 
+extern PGDLLIMPORT bool force_instrument;
+
 /* ----------------
  *		query descriptor:
  *
diff --git a/src/include/utils/guc_tables.h b/src/include/utils/guc_tables.h
index 8791660..3982a27 100644
--- a/src/include/utils/guc_tables.h
+++ b/src/include/utils/guc_tables.h
@@ -242,5 +242,6 @@ extern const char *config_enum_lookup_by_value(struct config_enum *record, int v
 extern bool config_enum_lookup_by_name(struct config_enum *record,
 									  const char *value, int *retval);
 
+extern void DefineCustomVariable(enum config_type type, const void *variable);
 
 #endif   /* GUC_TABLES_H */