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
