diff --git a/contrib/Makefile b/contrib/Makefile index 56f6772ba1..bbd43e1f66 100644 --- a/contrib/Makefile +++ b/contrib/Makefile @@ -1,4 +1,4 @@ -# $PostgreSQL: pgsql/contrib/Makefile,v 1.84 2008/07/29 18:31:20 tgl Exp $ +# $PostgreSQL: pgsql/contrib/Makefile,v 1.85 2008/11/19 02:59:28 tgl Exp $ subdir = contrib top_builddir = .. @@ -6,6 +6,7 @@ include $(top_builddir)/src/Makefile.global WANTED_DIRS = \ adminpack \ + auto_explain \ btree_gist \ chkpass \ citext \ diff --git a/contrib/README b/contrib/README index d1345f669a..060853fa21 100644 --- a/contrib/README +++ b/contrib/README @@ -28,6 +28,10 @@ adminpack - File and log manipulation routines, used by pgAdmin by Dave Page +auto_explain - + Log EXPLAIN output for long-running queries + by Takahiro Itagaki + btree_gist - Support for emulating BTREE indexing in GiST by Oleg Bartunov and Teodor Sigaev diff --git a/contrib/auto_explain/Makefile b/contrib/auto_explain/Makefile new file mode 100644 index 0000000000..e9eaae0ece --- /dev/null +++ b/contrib/auto_explain/Makefile @@ -0,0 +1,15 @@ +# $PostgreSQL: pgsql/contrib/auto_explain/Makefile,v 1.1 2008/11/19 02:59:28 tgl Exp $ + +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 0000000000..f681602022 --- /dev/null +++ b/contrib/auto_explain/auto_explain.c @@ -0,0 +1,228 @@ +/*------------------------------------------------------------------------- + * + * auto_explain.c + * + * + * Copyright (c) 2008, PostgreSQL Global Development Group + * + * IDENTIFICATION + * $PostgreSQL: pgsql/contrib/auto_explain/auto_explain.c,v 1.1 2008/11/19 02:59:28 tgl Exp $ + * + *------------------------------------------------------------------------- + */ +#include "postgres.h" + +#include "commands/explain.h" +#include "executor/instrument.h" +#include "utils/guc.h" + +PG_MODULE_MAGIC; + +#define GUCNAME(name) ("explain." name) + +/* GUC variables */ +static int explain_log_min_duration = -1; /* msec or -1 */ +static bool explain_log_analyze = false; +static bool explain_log_verbose = false; +static bool explain_log_nested = false; + +/* Current nesting depth of ExecutorRun calls */ +static int nesting_level = 0; + +/* Saved hook values in case of unload */ +static ExecutorStart_hook_type prev_ExecutorStart = NULL; +static ExecutorRun_hook_type prev_ExecutorRun = NULL; +static ExecutorEnd_hook_type prev_ExecutorEnd = NULL; + +#define auto_explain_enabled() \ + (explain_log_min_duration >= 0 && \ + (nesting_level == 0 || explain_log_nested)) + +void _PG_init(void); +void _PG_fini(void); + +static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags); +static void explain_ExecutorRun(QueryDesc *queryDesc, + ScanDirection direction, + long count); +static void explain_ExecutorEnd(QueryDesc *queryDesc); + + +/* + * Module load callback + */ +void +_PG_init(void) +{ + /* Define custom GUC variables. */ + DefineCustomIntVariable(GUCNAME("log_min_duration"), + "Sets the minimum execution time above which plans will be logged.", + "Zero prints all plans. -1 turns this feature off.", + &explain_log_min_duration, + -1, + -1, INT_MAX / 1000, + PGC_SUSET, + GUC_UNIT_MS, + NULL, + NULL); + + DefineCustomBoolVariable(GUCNAME("log_analyze"), + "Use EXPLAIN ANALYZE for plan logging.", + NULL, + &explain_log_analyze, + false, + PGC_SUSET, + 0, + NULL, + NULL); + + DefineCustomBoolVariable(GUCNAME("log_verbose"), + "Use EXPLAIN VERBOSE for plan logging.", + NULL, + &explain_log_verbose, + false, + PGC_SUSET, + 0, + NULL, + NULL); + + DefineCustomBoolVariable(GUCNAME("log_nested_statements"), + "Log nested statements.", + NULL, + &explain_log_nested, + false, + PGC_SUSET, + 0, + NULL, + NULL); + + /* Install hooks. */ + prev_ExecutorStart = ExecutorStart_hook; + ExecutorStart_hook = explain_ExecutorStart; + prev_ExecutorRun = ExecutorRun_hook; + ExecutorRun_hook = explain_ExecutorRun; + prev_ExecutorEnd = ExecutorEnd_hook; + ExecutorEnd_hook = explain_ExecutorEnd; +} + +/* + * Module unload callback + */ +void +_PG_fini(void) +{ + /* Uninstall hooks. */ + ExecutorStart_hook = prev_ExecutorStart; + ExecutorRun_hook = prev_ExecutorRun; + ExecutorEnd_hook = prev_ExecutorEnd; +} + +/* + * ExecutorStart hook: start up logging if needed + */ +void +explain_ExecutorStart(QueryDesc *queryDesc, int eflags) +{ + if (auto_explain_enabled()) + { + /* Enable per-node instrumentation iff log_analyze is required. */ + if (explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0) + queryDesc->doInstrument = true; + } + + if (prev_ExecutorStart) + prev_ExecutorStart(queryDesc, eflags); + else + standard_ExecutorStart(queryDesc, eflags); + + if (auto_explain_enabled()) + { + /* + * Set up to track total elapsed time in ExecutorRun. Make sure + * the space is allocated in the per-query context so it will go + * away at ExecutorEnd. + */ + if (queryDesc->totaltime == NULL) + { + MemoryContext oldcxt; + + oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt); + queryDesc->totaltime = InstrAlloc(1); + MemoryContextSwitchTo(oldcxt); + } + } +} + +/* + * ExecutorRun hook: all we need do is track nesting depth + */ +void +explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, long count) +{ + nesting_level++; + PG_TRY(); + { + if (prev_ExecutorRun) + prev_ExecutorRun(queryDesc, direction, count); + else + standard_ExecutorRun(queryDesc, direction, count); + nesting_level--; + } + PG_CATCH(); + { + nesting_level--; + PG_RE_THROW(); + } + PG_END_TRY(); +} + +/* + * ExecutorEnd hook: log results if needed + */ +void +explain_ExecutorEnd(QueryDesc *queryDesc) +{ + if (queryDesc->totaltime && auto_explain_enabled()) + { + double msec; + + /* + * Make sure stats accumulation is done. (Note: it's okay if + * several levels of hook all do this.) + */ + InstrEndLoop(queryDesc->totaltime); + + /* Log plan if duration is exceeded. */ + msec = queryDesc->totaltime->total * 1000.0; + if (msec >= explain_log_min_duration) + { + StringInfoData buf; + + initStringInfo(&buf); + ExplainPrintPlan(&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] = '\0'; + + /* + * Note: we rely on the existing logging of context or + * debug_query_string to identify just which statement is being + * reported. This isn't ideal but trying to do it here would + * often result in duplication. + */ + ereport(LOG, + (errmsg("duration: %.3f ms plan:\n%s", + msec, buf.data))); + + pfree(buf.data); + } + } + + if (prev_ExecutorEnd) + prev_ExecutorEnd(queryDesc); + else + standard_ExecutorEnd(queryDesc); +} diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml new file mode 100644 index 0000000000..c8215e0cc8 --- /dev/null +++ b/doc/src/sgml/auto-explain.sgml @@ -0,0 +1,176 @@ + + + + auto_explain + + + auto_explain + + + + The auto_explain module provides a means for + logging execution plans of slow statements automatically, without + having to run + by hand. This is especially helpful for tracking down un-optimized queries + in large applications. + + + + The module provides no SQL-accessible functions. To use it, simply + load it into the server. You can load it into an individual session: + + +LOAD 'auto_explain'; + + + (You must be superuser to do that.) More typical usage is to preload + it into all sessions by including auto_explain in + in + postgresql.conf. Then you can track unexpectedly slow queries + no matter when they happen. Of course there is a price in overhead for + that. + + + + Configuration parameters + + + There are several configuration parameters that control the behavior of + auto_explain. Note that the default behavior is + to do nothing, so you must set at least + explain.log_min_duration if you want any results. + + + + + + explain.log_min_duration (integer) + + + explain.log_min_duration configuration parameter + + + + explain.log_min_duration is the minimum statement + execution time, in milliseconds, that will cause the statement's plan to + be logged. Setting this to zero logs all plans. Minus-one (the default) + disables logging of plans. For example, if you set it to + 250ms then all statements that run 250ms or longer + will be logged. Only superusers can change this setting. + + + + + + + explain.log_analyze (boolean) + + + explain.log_analyze configuration parameter + + + + explain.log_analyze causes EXPLAIN ANALYZE + output, rather than just EXPLAIN output, to be printed + when an execution plan is logged. This parameter is off by default. + Only superusers can change this setting. + + + + When this parameter is on, per-plan-node timing occurs for all + statements executed, whether or not they run long enough to actually + get logged. This can have extremely negative impact on performance. + + + + + + + + explain.log_verbose (boolean) + + + explain.log_verbose configuration parameter + + + + explain.log_verbose causes EXPLAIN VERBOSE + output, rather than just EXPLAIN output, to be printed + when an execution plan is logged. This parameter is off by default. + Only superusers can change this setting. + + + + + + + explain.log_nested_statements (boolean) + + + explain.log_nested_statements configuration parameter + + + + explain.log_nested_statements causes nested + statements (statements executed inside a function) to be considered + for logging. When it is off, only top-level query plans are logged. This + parameter is off by default. Only superusers can change this setting. + + + + + + + In order to set these parameters in your postgresql.conf file, + you will need to add explain in + custom_variable_classes. Typical usage might be: + + + +# postgresql.conf +shared_preload_libraries = 'auto_explain' + +custom_variable_classes = 'explain' +explain.log_min_duration = '3s' + + + + + Example + + + postgres=# LOAD 'auto_explain'; + postgres=# SET explain.log_min_duration = 0; + postgres=# SELECT count(*) + FROM pg_class, pg_index + WHERE oid = indrelid AND indisunique; + + + + This might produce log output such as: + + + + 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; + + + + + Author + + + Takahiro Itagaki itagaki.takahiro@oss.ntt.co.jp + + + + diff --git a/doc/src/sgml/contrib.sgml b/doc/src/sgml/contrib.sgml index bac5044205..ecc5a0b23e 100644 --- a/doc/src/sgml/contrib.sgml +++ b/doc/src/sgml/contrib.sgml @@ -1,4 +1,4 @@ - + Additional Supplied Modules @@ -79,6 +79,7 @@ psql -d dbname -f SHAREDIR/contrib/module.sql &adminpack; + &auto-explain; &btree-gist; &chkpass; &citext; diff --git a/doc/src/sgml/filelist.sgml b/doc/src/sgml/filelist.sgml index 32aa90400b..ea1c7c274f 100644 --- a/doc/src/sgml/filelist.sgml +++ b/doc/src/sgml/filelist.sgml @@ -1,4 +1,4 @@ - + @@ -92,6 +92,7 @@ +