diff options
| -rw-r--r-- | contrib/Makefile | 3 | ||||
| -rw-r--r-- | contrib/README | 4 | ||||
| -rw-r--r-- | contrib/auto_explain/Makefile | 15 | ||||
| -rw-r--r-- | contrib/auto_explain/auto_explain.c | 228 | ||||
| -rw-r--r-- | doc/src/sgml/auto-explain.sgml | 176 | ||||
| -rw-r--r-- | doc/src/sgml/contrib.sgml | 3 | ||||
| -rw-r--r-- | doc/src/sgml/filelist.sgml | 3 |
7 files changed, 429 insertions, 3 deletions
diff --git a/contrib/Makefile b/contrib/Makefile index 56f6772ba1a..bbd43e1f661 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 d1345f669a0..060853fa216 100644 --- a/contrib/README +++ b/contrib/README @@ -28,6 +28,10 @@ adminpack - File and log manipulation routines, used by pgAdmin by Dave Page <dpage@vale-housing.co.uk> +auto_explain - + Log EXPLAIN output for long-running queries + by Takahiro Itagaki <itagaki.takahiro@oss.ntt.co.jp> + btree_gist - Support for emulating BTREE indexing in GiST by Oleg Bartunov <oleg@sai.msu.su> and Teodor Sigaev <teodor@sigaev.ru> diff --git a/contrib/auto_explain/Makefile b/contrib/auto_explain/Makefile new file mode 100644 index 00000000000..e9eaae0ece2 --- /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 00000000000..f6816020220 --- /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 00000000000..c8215e0cc81 --- /dev/null +++ b/doc/src/sgml/auto-explain.sgml @@ -0,0 +1,176 @@ +<!-- $PostgreSQL: pgsql/doc/src/sgml/auto-explain.sgml,v 1.1 2008/11/19 02:59:28 tgl Exp $ --> + +<sect1 id="auto-explain"> + <title>auto_explain</title> + + <indexterm zone="auto-explain"> + <primary>auto_explain</primary> + </indexterm> + + <para> + The <filename>auto_explain</filename> module provides a means for + logging execution plans of slow statements automatically, without + having to run <xref linkend="sql-explain" endterm="sql-explain-title"> + by hand. This is especially helpful for tracking down un-optimized queries + in large applications. + </para> + + <para> + The module provides no SQL-accessible functions. To use it, simply + load it into the server. You can load it into an individual session: + + <programlisting> +LOAD 'auto_explain'; + </programlisting> + + (You must be superuser to do that.) More typical usage is to preload + it into all sessions by including <literal>auto_explain</> in + <xref linkend="guc-shared-preload-libraries"> in + <filename>postgresql.conf</>. Then you can track unexpectedly slow queries + no matter when they happen. Of course there is a price in overhead for + that. + </para> + + <sect2> + <title>Configuration parameters</title> + + <para> + There are several configuration parameters that control the behavior of + <filename>auto_explain</filename>. Note that the default behavior is + to do nothing, so you must set at least + <varname>explain.log_min_duration</varname> if you want any results. + </para> + + <variablelist> + <varlistentry> + <term> + <varname>explain.log_min_duration</varname> (<type>integer</type>) + </term> + <indexterm> + <primary><varname>explain.log_min_duration</> configuration parameter</primary> + </indexterm> + <listitem> + <para> + <varname>explain.log_min_duration</varname> 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 + <literal>250ms</literal> then all statements that run 250ms or longer + will be logged. Only superusers can change this setting. + </para> + </listitem> + </varlistentry> + + <varlistentry> + <term> + <varname>explain.log_analyze</varname> (<type>boolean</type>) + </term> + <indexterm> + <primary><varname>explain.log_analyze</> configuration parameter</primary> + </indexterm> + <listitem> + <para> + <varname>explain.log_analyze</varname> causes <command>EXPLAIN ANALYZE</> + output, rather than just <command>EXPLAIN</> output, to be printed + when an execution plan is logged. This parameter is off by default. + Only superusers can change this setting. + </para> + <note> + <para> + 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. + </para> + </note> + </listitem> + </varlistentry> + + <varlistentry> + <term> + <varname>explain.log_verbose</varname> (<type>boolean</type>) + </term> + <indexterm> + <primary><varname>explain.log_verbose</> configuration parameter</primary> + </indexterm> + <listitem> + <para> + <varname>explain.log_verbose</varname> causes <command>EXPLAIN VERBOSE</> + output, rather than just <command>EXPLAIN</> output, to be printed + when an execution plan is logged. This parameter is off by default. + Only superusers can change this setting. + </para> + </listitem> + </varlistentry> + + <varlistentry> + <term> + <varname>explain.log_nested_statements</varname> (<type>boolean</type>) + </term> + <indexterm> + <primary><varname>explain.log_nested_statements</> configuration parameter</primary> + </indexterm> + <listitem> + <para> + <varname>explain.log_nested_statements</varname> 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. + </para> + </listitem> + </varlistentry> + </variablelist> + + <para> + In order to set these parameters in your <filename>postgresql.conf</> file, + you will need to add <literal>explain</> in + <varname>custom_variable_classes</>. Typical usage might be: + </para> + + <programlisting> +# postgresql.conf +shared_preload_libraries = 'auto_explain' + +custom_variable_classes = 'explain' +explain.log_min_duration = '3s' + </programlisting> + </sect2> + + <sect2> + <title>Example</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; + </programlisting> + + <para> + This might produce log output such as: + </para> + + <programlisting> + 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>Author</title> + + <para> + Takahiro Itagaki <email>itagaki.takahiro@oss.ntt.co.jp</email> + </para> + </sect2> + +</sect1> diff --git a/doc/src/sgml/contrib.sgml b/doc/src/sgml/contrib.sgml index bac5044205b..ecc5a0b23e3 100644 --- a/doc/src/sgml/contrib.sgml +++ b/doc/src/sgml/contrib.sgml @@ -1,4 +1,4 @@ -<!-- $PostgreSQL: pgsql/doc/src/sgml/contrib.sgml,v 1.9 2008/07/29 18:31:20 tgl Exp $ --> +<!-- $PostgreSQL: pgsql/doc/src/sgml/contrib.sgml,v 1.10 2008/11/19 02:59:28 tgl Exp $ --> <appendix id="contrib"> <title>Additional Supplied Modules</title> @@ -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 32aa90400bb..ea1c7c274fa 100644 --- a/doc/src/sgml/filelist.sgml +++ b/doc/src/sgml/filelist.sgml @@ -1,4 +1,4 @@ -<!-- $PostgreSQL: pgsql/doc/src/sgml/filelist.sgml,v 1.57 2008/07/29 18:31:20 tgl Exp $ --> +<!-- $PostgreSQL: pgsql/doc/src/sgml/filelist.sgml,v 1.58 2008/11/19 02:59:28 tgl Exp $ --> <!entity history SYSTEM "history.sgml"> <!entity info SYSTEM "info.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"> |