Add auto-explain contrib module for automatic logging of the plans of

slow-running queries.

Takahiro Itagaki

4 files changed, 249 insertions, 1 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);
+}