Ooops. That last patch had an embarrassing little typo which caused it to not
actually record the planner times.
This new version fixes that and also includes a little patch to psql so that it
ignores any backend notices during tab-completion, which otherwise just get
in the way. Trace during tab-completion still goes to the server log, if
enabled,
since this might actually be useful for debugging psql.
> * trace_min_planner_duration - int, PGC_USERSET
> * trace_min_executor_duration - int, PGC_USERSET
> * trace_explain_plan - bool, PGC_USERSET
>
I'm toying with the idea of adding another parameter, just for convenience:
* auto_trace = on | off
If trace_min_planner_duration and trace_min_executor_duration are both -1,
then setting auto_trace=on would be equivalent to setting
trace_min_planner_duration=0, trace_min_executor_duration=0 and
trace_explain_plan=on, causing *all* statements to be timed and explained
(similar to Oracle's AUTOTRACE).
If either of trace_min_planner_duration or trace_min_executor_duration
are> -1, then auto_trace will do nothing, and only those queries that are
slow to plan and/or execute would be logged.
I'll hold off actually do any more with this for now though, because I feel
that there are still a couple of questions not fully answered:
* Is a whole new logging level (TRACE) overkill for this, or would it
potentially have other uses in the future? My feeling is that it works quite
nicely.
* It it safe to open this up to ordinary users, or do more restrictions need
to be put on it, and if so what?
Regards, Dean
_________________________________________________________________
The John Lewis Clearance - save up to 50% with FREE delivery
http://clk.atdmt.com/UKM/go/101719806/direct/01/
*** ./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;
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
