On Thu, 2008-10-09 at 19:06 +0900, ITAGAKI Takahiro wrote: > Thanks for your reviewing, Alex. > I applied your comments to my patch. >
I made a few changes: 1. fixed some minor issues with auto_explain.sgml so that it would build (and renamed to auto-explain.sgml to match other files) 2. added link in contrib.sgml 3. added line to contrib/Makefile to build the module 4. bundled it all up as one patch to make it easier to move around It still needs to be merged with HEAD. Regards, Jeff Davis
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>[EMAIL PROTECTED]</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 */
-- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers