Hi,

This is a small patch I posted a few months back, and then kinda forgot
about / got distracted with other things.

Is there any interest in this? If so I am willing to put more work into
it, if people like it or have suggested improvements. Otherwise I'll let it
drop.

Here's what is does:

As it stands, basically it's just another debug parameter, called
debug_explain_plan, similar to debug_print_plan, except that the
output is in the form of EXPLAIN ANALYSE.

The main advantage it offers over a standard EXPLAIN ANALYSE is that
it explains *all* SQL executed, including any from within stored
prodecures and triggers, so it is quite useful for debugging these.

With a suitable logging level, it can also be used to produce very
verbose logfile output to help spot any inefficient database access by
other applications.

Example usage:

test=# SET debug_explain_plan=on;
SET
test=# SET client_min_messages=debug1;
SET
test=# CREATE TABLE foo(a int primary key);
NOTICE:  CREATE TABLE / PRIMARY KEY will create implicit index "foo_pkey" for 
table "foo"
CREATE TABLE
test=# INSERT INTO foo VALUES (1), (2), (3), (4), (5);
DEBUG:  ------------------- query plan -------------------
DETAIL:  Values Scan on "*VALUES*"  (cost=0.00..0.06 rows=5 width=4) (actual 
time=0.001..0.006 rows=5 loops=1)
Query runtime: 0.329 ms
INSERT 0 5
test=# CREATE FUNCTION foo() RETURNS int as 'select max(a) from foo;' LANGUAGE 
SQL STABLE;
CREATE FUNCTION
test=# SELECT * FROM foo WHERE a=foo();
DEBUG:  ------------------- query plan -------------------
DETAIL:  Result  (cost=0.04..0.05 rows=1 width=0) (actual time=0.044..0.044 
rows=1 loops=1)
  InitPlan
    ->  Limit  (cost=0.00..0.04 rows=1 width=4) (actual time=0.032..0.034 
rows=1 loops=1)
          ->  Index Scan Backward using foo_pkey on foo  (cost=0.00..84.25 
rows=2400 width=4) (actual time=0.025..0.025 rows=1 loops=1)
                Filter: (a IS NOT NULL)
Query runtime: 0.050 ms
CONTEXT:  SQL function "foo" statement 1
DEBUG:  ------------------- query plan -------------------
DETAIL:  Result  (cost=0.04..0.05 rows=1 width=0) (actual time=0.037..0.037 
rows=1 loops=1)
  InitPlan
    ->  Limit  (cost=0.00..0.04 rows=1 width=4) (actual time=0.027..0.029 
rows=1 loops=1)
          ->  Index Scan Backward using foo_pkey on foo  (cost=0.00..84.25 
rows=2400 width=4) (actual time=0.021..0.021 rows=1 loops=1)
                Filter: (a IS NOT NULL)
Query runtime: 0.044 ms
CONTEXT:  SQL function "foo" statement 1
DEBUG:  ------------------- query plan -------------------
DETAIL:  Index Scan using foo_pkey on foo  (cost=0.25..8.52 rows=1 width=4) 
(actual time=1.638..1.642 rows=1 loops=1)
  Index Cond: (a = foo())
Query runtime: 1.686 ms
 a
---
 5
(1 row)

test=# EXPLAIN SELECT * FROM foo WHERE a=foo();
DEBUG:  ------------------- query plan -------------------
DETAIL:  Result  (cost=0.04..0.05 rows=1 width=0) (actual time=0.012..0.012 
rows=1 loops=1)
  InitPlan
    ->  Limit  (cost=0.00..0.04 rows=1 width=4) (actual time=0.011..0.011 
rows=1 loops=1)
          ->  Index Scan Backward using foo_pkey on foo  (cost=0.00..84.25 
rows=2400 width=4) (actual time=0.010..0.010 rows=1 loops=1)
                Filter: (a IS NOT NULL)
Query runtime: 0.014 ms
CONTEXT:  SQL function "foo" statement 1
                             QUERY PLAN
--------------------------------------------------------------------
 Index Scan using foo_pkey on foo  (cost=0.25..8.52 rows=1 width=4)
   Index Cond: (a = foo())
(2 rows)

(The last example shows foo() being called during the planning of this
query, which explains why it is called twice during the previous execution)

Simon Riggs reviewed this last time and said that what this patch
currently does is probably not exactly what is wanted for PostgreSQL.
Possible improvements might be to integrate this with the EXPLAIN
command (eg. EXPLAIN TRACE query) and have a separate parameter
(log_explain) for logging purposes.

Comments?

Regards, Dean

_________________________________________________________________
Live Search Charades - guess correctly and find hidden videos
http://www.searchcharades.com/
*** ./doc/src/sgml/config.sgml.orig	Sun Jan 27 19:12:28 2008
--- ./doc/src/sgml/config.sgml	Sun Jan 27 21:58:32 2008
***************
*** 2790,2795 ****
--- 2790,2796 ----
        <term><varname>debug_print_rewritten</varname> (<type>boolean</type>)</term>
        <term><varname>debug_print_plan</varname> (<type>boolean</type>)</term>
        <term><varname>debug_pretty_print</varname> (<type>boolean</type>)</term>
+       <term><varname>debug_explain_plan</varname> (<type>boolean</type>)</term>
        <indexterm>
         <primary><varname>debug_print_parse</> configuration parameter</primary>
        </indexterm>
***************
*** 2802,2807 ****
--- 2803,2811 ----
        <indexterm>
         <primary><varname>debug_pretty_print</> configuration parameter</primary>
        </indexterm>
+       <indexterm>
+        <primary><varname>debug_explain_plan</> configuration parameter</primary>
+       </indexterm>
        <listitem>
         <para>
          These parameters enable various debugging output to be emitted.
***************
*** 2809,2820 ****
          the resulting parse tree, the query rewriter output, or the
          execution plan.  <varname>debug_pretty_print</varname> indents
          these displays to produce a more readable but much longer
!         output format.  <varname>client_min_messages</varname> or
          <varname>log_min_messages</varname> must be
          <literal>DEBUG1</literal> or lower to actually send this output
          to the client or the server log, respectively.
          These parameters are off by default.
         </para>
        </listitem>
       </varlistentry>
  
--- 2813,2837 ----
          the resulting parse tree, the query rewriter output, or the
          execution plan.  <varname>debug_pretty_print</varname> indents
          these displays to produce a more readable but much longer
!         output format.  <varname>debug_explain_plan</varname> prints
!         the plan for each executed query in the same format as
!         <command>EXPLAIN ANALYZE</>. This includes queries executed from
!         within functions.  <varname>client_min_messages</varname> or
          <varname>log_min_messages</varname> must be
          <literal>DEBUG1</literal> or lower to actually send this output
          to the client or the server log, respectively.
          These parameters are off by default.
         </para>
+ 
+        <note>
+         <para>
+          The reports produced by <varname>debug_explain_plan</varname>
+          are produced at a lower level in the database, as each query
+          is executed, including queries executed from functions, so
+          the output may be more verbose that of <command>EXPLAIN ANALYZE</>
+          and the timings may differ.
+         </para>
+        </note>
        </listitem>
       </varlistentry>
  
*** ./src/backend/commands/explain.c.orig	Tue Jan  1 19:45:50 2008
--- ./src/backend/commands/explain.c	Sat Jan 26 11:55:54 2008
***************
*** 39,65 ****
  /* Hook for plugins to get control in explain_get_index_name() */
  explain_get_index_name_hook_type explain_get_index_name_hook = NULL;
  
- 
- typedef struct ExplainState
- {
- 	/* options */
- 	bool		printNodes;		/* do nodeToString() too */
- 	bool		printAnalyze;	/* print actual times */
- 	/* other states */
- 	PlannedStmt *pstmt;			/* top of plan */
- 	List	   *rtable;			/* range table */
- } ExplainState;
- 
  static void ExplainOneQuery(Query *query, ExplainStmt *stmt,
  				const char *queryString,
  				ParamListInfo params, TupOutputState *tstate);
  static void report_triggers(ResultRelInfo *rInfo, bool show_relname,
  				StringInfo buf);
- static double elapsed_time(instr_time *starttime);
- static void explain_outNode(StringInfo str,
- 				Plan *plan, PlanState *planstate,
- 				Plan *outer_plan,
- 				int indent, ExplainState *es);
  static void show_scan_qual(List *qual, const char *qlabel,
  			   int scanrelid, Plan *outer_plan, Plan *inner_plan,
  			   StringInfo str, int indent, ExplainState *es);
--- 39,49 ----
***************
*** 402,408 ****
  }
  
  /* Compute elapsed time in seconds since given timestamp */
! static double
  elapsed_time(instr_time *starttime)
  {
  	instr_time	endtime;
--- 386,392 ----
  }
  
  /* Compute elapsed time in seconds since given timestamp */
! double
  elapsed_time(instr_time *starttime)
  {
  	instr_time	endtime;
***************
*** 436,442 ****
   * side of a join with the current node.  This is only interesting for
   * deciphering runtime keys of an inner indexscan.
   */
! static void
  explain_outNode(StringInfo str,
  				Plan *plan, PlanState *planstate,
  				Plan *outer_plan,
--- 420,426 ----
   * side of a join with the current node.  This is only interesting for
   * deciphering runtime keys of an inner indexscan.
   */
! void
  explain_outNode(StringInfo str,
  				Plan *plan, PlanState *planstate,
  				Plan *outer_plan,
*** ./src/backend/executor/execMain.c.orig	Tue Jan  1 19:45:50 2008
--- ./src/backend/executor/execMain.c	Sat Jan 26 14:34:26 2008
***************
*** 39,44 ****
--- 39,45 ----
  #include "catalog/heap.h"
  #include "catalog/namespace.h"
  #include "catalog/toasting.h"
+ #include "commands/explain.h"
  #include "commands/tablespace.h"
  #include "commands/trigger.h"
  #include "executor/execdebug.h"
***************
*** 52,57 ****
--- 53,59 ----
  #include "utils/acl.h"
  #include "utils/lsyscache.h"
  #include "utils/memutils.h"
+ #include "utils/guc.h"
  
  
  typedef struct evalPlanQual
***************
*** 185,190 ****
--- 187,198 ----
  	}
  
  	/*
+ 	 * If we are explaining all queries, enable instrumentation
+ 	 */
+ 	if (Debug_explain_plan)
+ 		queryDesc->doInstrument = true;
+ 
+ 	/*
  	 * Copy other important information into the EState
  	 */
  	estate->es_snapshot = queryDesc->snapshot;
***************
*** 227,232 ****
--- 235,243 ----
  	bool		sendTuples;
  	TupleTableSlot *result;
  	MemoryContext oldcontext;
+ 	bool		explainPlan = Debug_explain_plan;
+ 	instr_time	starttime;
+ 	double		totaltime;
  
  	/* sanity checks */
  	Assert(queryDesc != NULL);
***************
*** 236,241 ****
--- 247,263 ----
  	Assert(estate != NULL);
  
  	/*
+ 	 * If explaining all queries, record the start time before running
+ 	 * the query. This is not quite the same as EXPLAIN ANALYSE, which
+ 	 * starts timing before ExecutorStart(). Here we are only timing
+ 	 * how long the query takes to run, once initialised and also
+ 	 * excluding any triggers (which may themselves run queries which
+ 	 * will be instrumented separately).
+ 	 */
+ 	if (explainPlan)
+ 		INSTR_TIME_SET_CURRENT(starttime);
+ 
+ 	/*
  	 * Switch into per-query memory context
  	 */
  	oldcontext = MemoryContextSwitchTo(estate->es_query_cxt);
***************
*** 278,283 ****
--- 300,340 ----
  		(*dest->rShutdown) (dest);
  
  	MemoryContextSwitchTo(oldcontext);
+ 
+ 	/*
+ 	 * If explaining all queries, log the execution plan using
+ 	 * the same format as EXPLAIN ANALYSE
+ 	 */
+ 	if (explainPlan)
+ 	{
+ 		ExplainState *es;
+ 		StringInfoData buf;
+ 
+ 		totaltime = elapsed_time(&starttime);
+ 
+ 		es = (ExplainState *) palloc0(sizeof(ExplainState));
+ 
+ 		es->printNodes = false;
+ 		es->printAnalyze = true;
+ 		es->pstmt = queryDesc->plannedstmt;
+ 		es->rtable = queryDesc->plannedstmt->rtable;
+ 
+ 		initStringInfo(&buf);
+ 		explain_outNode(&buf,
+ 						queryDesc->plannedstmt->planTree,
+ 						queryDesc->planstate,
+ 						NULL, 0, es);
+ 
+ 		appendStringInfo(&buf, "Query runtime: %.3f ms",
+ 						 1000.0 * totaltime);
+ 
+ 		ereport(DEBUG1,
+ 				(errmsg("------------------- query plan -------------------"),
+ 				 errdetail("%s", buf.data)));
+ 
+ 		pfree(buf.data);
+ 		pfree(es);
+ 	}
  
  	return result;
  }
*** ./src/backend/utils/misc/guc.c.orig	Sun Jan 27 19:12:28 2008
--- ./src/backend/utils/misc/guc.c	Sun Jan 27 21:52:58 2008
***************
*** 193,198 ****
--- 193,199 ----
  bool		Debug_print_rewritten = false;
  bool		Debug_pretty_print = false;
  bool		Explain_pretty_print = true;
+ bool		Debug_explain_plan = false;
  
  bool		log_parser_stats = false;
  bool		log_planner_stats = false;
***************
*** 682,687 ****
--- 683,696 ----
  			NULL
  		},
  		&Debug_pretty_print,
+ 		false, NULL, NULL
+ 	},
+ 	{
+ 		{"debug_explain_plan", PGC_USERSET, LOGGING_WHAT,
+ 			gettext_noop("Explains the execution plan to server log."),
+ 			NULL
+ 		},
+ 		&Debug_explain_plan,
  		false, NULL, NULL
  	},
  	{
*** ./src/backend/utils/misc/postgresql.conf.sample.orig	Sun Jan 27 19:12:28 2008
--- ./src/backend/utils/misc/postgresql.conf.sample	Sun Jan 27 21:54:26 2008
***************
*** 323,328 ****
--- 323,329 ----
  #debug_print_rewritten = off
  #debug_print_plan = off
  #debug_pretty_print = off
+ #debug_explain_plan = off
  #log_checkpoints = off
  #log_connections = off
  #log_disconnections = off
*** ./src/include/commands/explain.h.orig	Tue Jan  1 19:45:58 2008
--- ./src/include/commands/explain.h	Sat Jan 26 11:53:48 2008
***************
*** 14,19 ****
--- 14,30 ----
  #define EXPLAIN_H
  
  #include "executor/executor.h"
+ #include "executor/instrument.h"
+ 
+ typedef struct ExplainState
+ {
+ 	/* options */
+ 	bool		printNodes;		/* do nodeToString() too */
+ 	bool		printAnalyze;	/* print actual times */
+ 	/* other states */
+ 	PlannedStmt *pstmt;			/* top of plan */
+ 	List	   *rtable;			/* range table */
+ } ExplainState;
  
  /* Hook for plugins to get control in ExplainOneQuery() */
  typedef void (*ExplainOneQuery_hook_type) (Query *query,
***************
*** 40,44 ****
--- 51,62 ----
  
  extern void ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params,
  			   ExplainStmt *stmt, TupOutputState *tstate);
+ 
+ extern void explain_outNode(StringInfo str,
+ 				Plan *plan, PlanState *planstate,
+ 				Plan *outer_plan,
+ 				int indent, ExplainState *es);
+ 
+ extern double elapsed_time(instr_time *starttime);
  
  #endif   /* EXPLAIN_H */
*** ./src/include/utils/guc.h.orig	Tue Jan  1 19:46:00 2008
--- ./src/include/utils/guc.h	Sat Jan 26 11:51:42 2008
***************
*** 117,122 ****
--- 117,123 ----
  extern bool Debug_print_rewritten;
  extern bool Debug_pretty_print;
  extern bool Explain_pretty_print;
+ extern bool Debug_explain_plan;
  
  extern bool log_parser_stats;
  extern bool log_planner_stats;
-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Reply via email to