slow-running queries.
Takahiro Itagaki
-# $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 = ..
WANTED_DIRS = \
adminpack \
+ auto_explain \
btree_gist \
chkpass \
citext \
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>
--- /dev/null
+# $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
--- /dev/null
+/*-------------------------------------------------------------------------
+ *
+ * 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);
+}
--- /dev/null
+<!-- $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>
-<!-- $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>
</para>
&adminpack;
+ &auto-explain;
&btree-gist;
&chkpass;
&citext;
-<!-- $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">
<!-- 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">
OSDN Git Service
