Adding upstream version 15.4.upstream/15.4upstream

Signed-off-by: Daniel Baumann <daniel.baumann@progress-linux.org>

4 files changed, 602 insertions, 0 deletions

diff --git a/contrib/auto_explain/.gitignore b/contrib/auto_explain/.gitignore
new file mode 100644
index 0000000..5dcb3ff
--- /dev/null
+++ b/contrib/auto_explain/.gitignore
@@ -0,0 +1,4 @@
+# Generated subdirectories
+/log/
+/results/
+/tmp_check/
diff --git a/contrib/auto_explain/Makefile b/contrib/auto_explain/Makefile
new file mode 100644
index 0000000..efd127d
--- /dev/null
+++ b/contrib/auto_explain/Makefile
@@ -0,0 +1,20 @@
+# contrib/auto_explain/Makefile
+
+MODULE_big = auto_explain
+OBJS = \
+	$(WIN32RES) \
+	auto_explain.o
+PGFILEDESC = "auto_explain - logging facility for execution plans"
+
+TAP_TESTS = 1
+
+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..c9a0d94
--- /dev/null
+++ b/contrib/auto_explain/auto_explain.c
@@ -0,0 +1,429 @@
+/*-------------------------------------------------------------------------
+ *
+ * auto_explain.c
+ *
+ *
+ * Copyright (c) 2008-2022, PostgreSQL Global Development Group
+ *
+ * IDENTIFICATION
+ *	  contrib/auto_explain/auto_explain.c
+ *
+ *-------------------------------------------------------------------------
+ */
+#include "postgres.h"
+
+#include <limits.h>
+
+#include "access/parallel.h"
+#include "commands/explain.h"
+#include "common/pg_prng.h"
+#include "executor/instrument.h"
+#include "jit/jit.h"
+#include "utils/guc.h"
+
+PG_MODULE_MAGIC;
+
+/* GUC variables */
+static int	auto_explain_log_min_duration = -1; /* msec or -1 */
+static bool auto_explain_log_analyze = false;
+static bool auto_explain_log_verbose = false;
+static bool auto_explain_log_buffers = false;
+static bool auto_explain_log_wal = false;
+static bool auto_explain_log_triggers = false;
+static bool auto_explain_log_timing = true;
+static bool auto_explain_log_settings = false;
+static int	auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
+static int	auto_explain_log_level = LOG;
+static bool auto_explain_log_nested_statements = false;
+static double auto_explain_sample_rate = 1;
+
+static const struct config_enum_entry format_options[] = {
+	{"text", EXPLAIN_FORMAT_TEXT, false},
+	{"xml", EXPLAIN_FORMAT_XML, false},
+	{"json", EXPLAIN_FORMAT_JSON, false},
+	{"yaml", EXPLAIN_FORMAT_YAML, false},
+	{NULL, 0, false}
+};
+
+static const struct config_enum_entry loglevel_options[] = {
+	{"debug5", DEBUG5, false},
+	{"debug4", DEBUG4, false},
+	{"debug3", DEBUG3, false},
+	{"debug2", DEBUG2, false},
+	{"debug1", DEBUG1, false},
+	{"debug", DEBUG2, true},
+	{"info", INFO, false},
+	{"notice", NOTICE, false},
+	{"warning", WARNING, false},
+	{"log", LOG, false},
+	{NULL, 0, false}
+};
+
+/* Current nesting depth of ExecutorRun calls */
+static int	nesting_level = 0;
+
+/* Is the current top-level query to be sampled? */
+static bool current_query_sampled = false;
+
+#define auto_explain_enabled() \
+	(auto_explain_log_min_duration >= 0 && \
+	 (nesting_level == 0 || auto_explain_log_nested_statements) && \
+	 current_query_sampled)
+
+/* Saved hook values in case of unload */
+static ExecutorStart_hook_type prev_ExecutorStart = NULL;
+static ExecutorRun_hook_type prev_ExecutorRun = NULL;
+static ExecutorFinish_hook_type prev_ExecutorFinish = NULL;
+static ExecutorEnd_hook_type prev_ExecutorEnd = NULL;
+
+void		_PG_init(void);
+
+static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags);
+static void explain_ExecutorRun(QueryDesc *queryDesc,
+								ScanDirection direction,
+								uint64 count, bool execute_once);
+static void explain_ExecutorFinish(QueryDesc *queryDesc);
+static void explain_ExecutorEnd(QueryDesc *queryDesc);
+
+
+/*
+ * Module load callback
+ */
+void
+_PG_init(void)
+{
+	/* Define custom GUC variables. */
+	DefineCustomIntVariable("auto_explain.log_min_duration",
+							"Sets the minimum execution time above which plans will be logged.",
+							"Zero prints all plans. -1 turns this feature off.",
+							&auto_explain_log_min_duration,
+							-1,
+							-1, INT_MAX,
+							PGC_SUSET,
+							GUC_UNIT_MS,
+							NULL,
+							NULL,
+							NULL);
+
+	DefineCustomBoolVariable("auto_explain.log_analyze",
+							 "Use EXPLAIN ANALYZE for plan logging.",
+							 NULL,
+							 &auto_explain_log_analyze,
+							 false,
+							 PGC_SUSET,
+							 0,
+							 NULL,
+							 NULL,
+							 NULL);
+
+	DefineCustomBoolVariable("auto_explain.log_settings",
+							 "Log modified configuration parameters affecting query planning.",
+							 NULL,
+							 &auto_explain_log_settings,
+							 false,
+							 PGC_SUSET,
+							 0,
+							 NULL,
+							 NULL,
+							 NULL);
+
+	DefineCustomBoolVariable("auto_explain.log_verbose",
+							 "Use EXPLAIN VERBOSE for plan logging.",
+							 NULL,
+							 &auto_explain_log_verbose,
+							 false,
+							 PGC_SUSET,
+							 0,
+							 NULL,
+							 NULL,
+							 NULL);
+
+	DefineCustomBoolVariable("auto_explain.log_buffers",
+							 "Log buffers usage.",
+							 NULL,
+							 &auto_explain_log_buffers,
+							 false,
+							 PGC_SUSET,
+							 0,
+							 NULL,
+							 NULL,
+							 NULL);
+
+	DefineCustomBoolVariable("auto_explain.log_wal",
+							 "Log WAL usage.",
+							 NULL,
+							 &auto_explain_log_wal,
+							 false,
+							 PGC_SUSET,
+							 0,
+							 NULL,
+							 NULL,
+							 NULL);
+
+	DefineCustomBoolVariable("auto_explain.log_triggers",
+							 "Include trigger statistics in plans.",
+							 "This has no effect unless log_analyze is also set.",
+							 &auto_explain_log_triggers,
+							 false,
+							 PGC_SUSET,
+							 0,
+							 NULL,
+							 NULL,
+							 NULL);
+
+	DefineCustomEnumVariable("auto_explain.log_format",
+							 "EXPLAIN format to be used for plan logging.",
+							 NULL,
+							 &auto_explain_log_format,
+							 EXPLAIN_FORMAT_TEXT,
+							 format_options,
+							 PGC_SUSET,
+							 0,
+							 NULL,
+							 NULL,
+							 NULL);
+
+	DefineCustomEnumVariable("auto_explain.log_level",
+							 "Log level for the plan.",
+							 NULL,
+							 &auto_explain_log_level,
+							 LOG,
+							 loglevel_options,
+							 PGC_SUSET,
+							 0,
+							 NULL,
+							 NULL,
+							 NULL);
+
+	DefineCustomBoolVariable("auto_explain.log_nested_statements",
+							 "Log nested statements.",
+							 NULL,
+							 &auto_explain_log_nested_statements,
+							 false,
+							 PGC_SUSET,
+							 0,
+							 NULL,
+							 NULL,
+							 NULL);
+
+	DefineCustomBoolVariable("auto_explain.log_timing",
+							 "Collect timing data, not just row counts.",
+							 NULL,
+							 &auto_explain_log_timing,
+							 true,
+							 PGC_SUSET,
+							 0,
+							 NULL,
+							 NULL,
+							 NULL);
+
+	DefineCustomRealVariable("auto_explain.sample_rate",
+							 "Fraction of queries to process.",
+							 NULL,
+							 &auto_explain_sample_rate,
+							 1.0,
+							 0.0,
+							 1.0,
+							 PGC_SUSET,
+							 0,
+							 NULL,
+							 NULL,
+							 NULL);
+
+	MarkGUCPrefixReserved("auto_explain");
+
+	/* Install hooks. */
+	prev_ExecutorStart = ExecutorStart_hook;
+	ExecutorStart_hook = explain_ExecutorStart;
+	prev_ExecutorRun = ExecutorRun_hook;
+	ExecutorRun_hook = explain_ExecutorRun;
+	prev_ExecutorFinish = ExecutorFinish_hook;
+	ExecutorFinish_hook = explain_ExecutorFinish;
+	prev_ExecutorEnd = ExecutorEnd_hook;
+	ExecutorEnd_hook = explain_ExecutorEnd;
+}
+
+/*
+ * ExecutorStart hook: start up logging if needed
+ */
+static void
+explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
+{
+	/*
+	 * At the beginning of each top-level statement, decide whether we'll
+	 * sample this statement.  If nested-statement explaining is enabled,
+	 * either all nested statements will be explained or none will.
+	 *
+	 * When in a parallel worker, we should do nothing, which we can implement
+	 * cheaply by pretending we decided not to sample the current statement.
+	 * If EXPLAIN is active in the parent session, data will be collected and
+	 * reported back to the parent, and it's no business of ours to interfere.
+	 */
+	if (nesting_level == 0)
+	{
+		if (auto_explain_log_min_duration >= 0 && !IsParallelWorker())
+			current_query_sampled = (pg_prng_double(&pg_global_prng_state) < auto_explain_sample_rate);
+		else
+			current_query_sampled = false;
+	}
+
+	if (auto_explain_enabled())
+	{
+		/* Enable per-node instrumentation iff log_analyze is required. */
+		if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
+		{
+			if (auto_explain_log_timing)
+				queryDesc->instrument_options |= INSTRUMENT_TIMER;
+			else
+				queryDesc->instrument_options |= INSTRUMENT_ROWS;
+			if (auto_explain_log_buffers)
+				queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
+			if (auto_explain_log_wal)
+				queryDesc->instrument_options |= INSTRUMENT_WAL;
+		}
+	}
+
+	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, INSTRUMENT_ALL, false);
+			MemoryContextSwitchTo(oldcxt);
+		}
+	}
+}
+
+/*
+ * ExecutorRun hook: all we need do is track nesting depth
+ */
+static void
+explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction,
+					uint64 count, bool execute_once)
+{
+	nesting_level++;
+	PG_TRY();
+	{
+		if (prev_ExecutorRun)
+			prev_ExecutorRun(queryDesc, direction, count, execute_once);
+		else
+			standard_ExecutorRun(queryDesc, direction, count, execute_once);
+	}
+	PG_FINALLY();
+	{
+		nesting_level--;
+	}
+	PG_END_TRY();
+}
+
+/*
+ * ExecutorFinish hook: all we need do is track nesting depth
+ */
+static void
+explain_ExecutorFinish(QueryDesc *queryDesc)
+{
+	nesting_level++;
+	PG_TRY();
+	{
+		if (prev_ExecutorFinish)
+			prev_ExecutorFinish(queryDesc);
+		else
+			standard_ExecutorFinish(queryDesc);
+	}
+	PG_FINALLY();
+	{
+		nesting_level--;
+	}
+	PG_END_TRY();
+}
+
+/*
+ * ExecutorEnd hook: log results if needed
+ */
+static void
+explain_ExecutorEnd(QueryDesc *queryDesc)
+{
+	if (queryDesc->totaltime && auto_explain_enabled())
+	{
+		MemoryContext oldcxt;
+		double		msec;
+
+		/*
+		 * Make sure we operate in the per-query context, so any cruft will be
+		 * discarded later during ExecutorEnd.
+		 */
+		oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
+
+		/*
+		 * 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 >= auto_explain_log_min_duration)
+		{
+			ExplainState *es = NewExplainState();
+
+			es->analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
+			es->verbose = auto_explain_log_verbose;
+			es->buffers = (es->analyze && auto_explain_log_buffers);
+			es->wal = (es->analyze && auto_explain_log_wal);
+			es->timing = (es->analyze && auto_explain_log_timing);
+			es->summary = es->analyze;
+			es->format = auto_explain_log_format;
+			es->settings = auto_explain_log_settings;
+
+			ExplainBeginOutput(es);
+			ExplainQueryText(es, queryDesc);
+			ExplainPrintPlan(es, queryDesc);
+			if (es->analyze && auto_explain_log_triggers)
+				ExplainPrintTriggers(es, queryDesc);
+			if (es->costs)
+				ExplainPrintJITSummary(es, queryDesc);
+			ExplainEndOutput(es);
+
+			/* Remove last line break */
+			if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
+				es->str->data[--es->str->len] = '\0';
+
+			/* Fix JSON to output an object */
+			if (auto_explain_log_format == EXPLAIN_FORMAT_JSON)
+			{
+				es->str->data[0] = '{';
+				es->str->data[es->str->len - 1] = '}';
+			}
+
+			/*
+			 * 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(auto_explain_log_level,
+					(errmsg("duration: %.3f ms  plan:\n%s",
+							msec, es->str->data),
+					 errhidestmt(true)));
+		}
+
+		MemoryContextSwitchTo(oldcxt);
+	}
+
+	if (prev_ExecutorEnd)
+		prev_ExecutorEnd(queryDesc);
+	else
+		standard_ExecutorEnd(queryDesc);
+}
diff --git a/contrib/auto_explain/t/001_auto_explain.pl b/contrib/auto_explain/t/001_auto_explain.pl
new file mode 100644
index 0000000..2f2e7fb
--- /dev/null
+++ b/contrib/auto_explain/t/001_auto_explain.pl
@@ -0,0 +1,149 @@
+
+# Copyright (c) 2021-2022, PostgreSQL Global Development Group
+
+use strict;
+use warnings;
+
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+use Test::More;
+
+# Runs the specified query and returns the emitted server log.
+# params is an optional hash mapping GUC names to values;
+# any such settings are transmitted to the backend via PGOPTIONS.
+sub query_log
+{
+	my ($node, $sql, $params) = @_;
+	$params ||= {};
+
+	local $ENV{PGOPTIONS} = join " ",
+	  map { "-c $_=$params->{$_}" } keys %$params;
+
+	my $log    = $node->logfile();
+	my $offset = -s $log;
+
+	$node->safe_psql("postgres", $sql);
+
+	return slurp_file($log, $offset);
+}
+
+my $node = PostgreSQL::Test::Cluster->new('main');
+$node->init('auth_extra' => [ '--create-role', 'regress_user1' ]);
+$node->append_conf('postgresql.conf',
+	"session_preload_libraries = 'auto_explain'");
+$node->append_conf('postgresql.conf', "auto_explain.log_min_duration = 0");
+$node->append_conf('postgresql.conf', "auto_explain.log_analyze = on");
+$node->start;
+
+# Simple query.
+my $log_contents = query_log($node, "SELECT * FROM pg_class;");
+
+like(
+	$log_contents,
+	qr/Query Text: SELECT \* FROM pg_class;/,
+	"query text logged, text mode");
+
+unlike(
+	$log_contents,
+	qr/Query Parameters:/,
+	"no query parameters logged when none, text mode");
+
+like(
+	$log_contents,
+	qr/Seq Scan on pg_class/,
+	"sequential scan logged, text mode");
+
+# Prepared query.
+$log_contents = query_log($node,
+	q{PREPARE get_proc(name) AS SELECT * FROM pg_proc WHERE proname = $1; EXECUTE get_proc('int4pl');}
+);
+
+like(
+	$log_contents,
+	qr/Query Text: PREPARE get_proc\(name\) AS SELECT \* FROM pg_proc WHERE proname = \$1;/,
+	"prepared query text logged, text mode");
+
+like(
+	$log_contents,
+	qr/Index Scan using pg_proc_proname_args_nsp_index on pg_proc/,
+	"index scan logged, text mode");
+
+
+# JSON format.
+$log_contents = query_log(
+	$node,
+	"SELECT * FROM pg_class;",
+	{ "auto_explain.log_format" => "json" });
+
+like(
+	$log_contents,
+	qr/"Query Text": "SELECT \* FROM pg_class;"/,
+	"query text logged, json mode");
+
+unlike(
+	$log_contents,
+	qr/"Query Parameters":/,
+	"query parameters not logged when none, json mode");
+
+like(
+	$log_contents,
+	qr/"Node Type": "Seq Scan"[^}]*"Relation Name": "pg_class"/s,
+	"sequential scan logged, json mode");
+
+# Prepared query in JSON format.
+$log_contents = query_log(
+	$node,
+	q{PREPARE get_class(name) AS SELECT * FROM pg_class WHERE relname = $1; EXECUTE get_class('pg_class');},
+	{ "auto_explain.log_format" => "json" });
+
+like(
+	$log_contents,
+	qr/"Query Text": "PREPARE get_class\(name\) AS SELECT \* FROM pg_class WHERE relname = \$1;"/,
+	"prepared query text logged, json mode");
+
+like(
+	$log_contents,
+	qr/"Node Type": "Index Scan"[^}]*"Index Name": "pg_class_relname_nsp_index"/s,
+	"index scan logged, json mode");
+
+# Check that PGC_SUSET parameters can be set by non-superuser if granted,
+# otherwise not
+
+$node->safe_psql(
+	"postgres", q{
+CREATE USER regress_user1;
+GRANT SET ON PARAMETER auto_explain.log_format TO regress_user1;
+});
+
+{
+	local $ENV{PGUSER} = "regress_user1";
+
+	$log_contents = query_log(
+		$node,
+		"SELECT * FROM pg_database;",
+		{ "auto_explain.log_format" => "json" });
+
+	like(
+		$log_contents,
+		qr/"Query Text": "SELECT \* FROM pg_database;"/,
+		"query text logged, json mode selected by non-superuser");
+
+	$log_contents = query_log(
+		$node,
+		"SELECT * FROM pg_database;",
+		{ "auto_explain.log_level" => "log" });
+
+	like(
+		$log_contents,
+		qr/WARNING: ( 42501:)? permission denied to set parameter "auto_explain\.log_level"/,
+		"permission failure logged");
+
+}    # end queries run as regress_user1
+
+$node->safe_psql(
+	"postgres", q{
+REVOKE SET ON PARAMETER auto_explain.log_format FROM regress_user1;
+DROP USER regress_user1;
+});
+
+done_testing();