> After sleeping on this, I think we should follow your idea.
>
Hmm. I preferred your idea ;-) It reduces the number of new parameters
back down to 3, which makes it easier to use:
* trace_min_planner_duration - int, PGC_USERSET
* trace_min_executor_duration - int, PGC_USERSET
* trace_explain_plan - bool, PGC_USERSET
(I already decided to drop the "sql_") with all output going to new level TRACE
as you described. So output goes to client and not server log by default as
soon as either of the first 2 parameters is enabled.
I've attached what I've done so far, which works according to the above
description. I've not done much testing or written any docs yet, It would be
good to know if this is along the right lines.
Changing parameter names is easy, although admittedly very important to
get right. You didn't say why you changed your mind on this?
I'm more concerned about any possible security holes it opens up.
For SQL in SQL functions, it just gives the function name and statement
number. For EXECUTEd queries, it doesn't have access to the SQL, so
it just logs the other stuff and any context info. For plpgsql functions it will
log values which appear as literals in any queries, but actually
debug_print_parse exposes far more info in this case.
_________________________________________________________________
100’s of Nikon cameras to be won with Live Search
http://clk.atdmt.com/UKM/go/101719808/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 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;
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
