postgresql/contrib/auto_explain/auto_explain.c

/*-------------------------------------------------------------------------
 *
 * auto_explain.c
 *
 *
 * Copyright (c) 2008-2026, PostgreSQL Global Development Group
 *
 * IDENTIFICATION
 *	  contrib/auto_explain/auto_explain.c
 *
 *-------------------------------------------------------------------------
 */
#include "postgres.h"

#include <limits.h>

#include "access/parallel.h"
#include "commands/defrem.h"
#include "commands/explain.h"
#include "commands/explain_format.h"
#include "commands/explain_state.h"
#include "common/pg_prng.h"
#include "executor/instrument.h"
#include "nodes/makefuncs.h"
#include "nodes/value.h"
#include "parser/scansup.h"
#include "utils/guc.h"
#include "utils/varlena.h"

PG_MODULE_MAGIC_EXT(
					.name = "auto_explain",
					.version = PG_VERSION
);

/* GUC variables */
static int	auto_explain_log_min_duration = -1; /* msec or -1 */
static int	auto_explain_log_parameter_max_length = -1; /* bytes 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_io = 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 char *auto_explain_log_extension_options = NULL;

/*
 * Parsed form of one option from auto_explain.log_extension_options.
 */
typedef struct auto_explain_option
{
	char	   *name;
	char	   *value;
	NodeTag		type;
} auto_explain_option;

/*
 * Parsed form of the entirety of auto_explain.log_extension_options, stored
 * as GUC extra. The options[] array will have pointers into the string
 * following the array.
 */
typedef struct auto_explain_extension_options
{
	int			noptions;
	auto_explain_option options[FLEXIBLE_ARRAY_MEMBER];
	/* a null-terminated copy of the GUC string follows the array */
} auto_explain_extension_options;

static auto_explain_extension_options *extension_options = NULL;

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 */
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;

static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags);
static void explain_ExecutorRun(QueryDesc *queryDesc,
								ScanDirection direction,
								uint64 count);
static void explain_ExecutorFinish(QueryDesc *queryDesc);
static void explain_ExecutorEnd(QueryDesc *queryDesc);

static bool check_log_extension_options(char **newval, void **extra,
										GucSource source);
static void assign_log_extension_options(const char *newval, void *extra);
static void apply_extension_options(ExplainState *es,
									auto_explain_extension_options *ext);
static char *auto_explain_scan_literal(char **endp, char **nextp);
static int	auto_explain_split_options(char *rawstring,
									   auto_explain_option *options,
									   int maxoptions, char **errmsg);

/*
 * 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.",
							"-1 disables logging plans. 0 means log all plans.",
							&auto_explain_log_min_duration,
							-1,
							-1, INT_MAX,
							PGC_SUSET,
							GUC_UNIT_MS,
							NULL,
							NULL,
							NULL);

	DefineCustomIntVariable("auto_explain.log_parameter_max_length",
							"Sets the maximum length of query parameter values to log.",
							"-1 means log values in full.",
							&auto_explain_log_parameter_max_length,
							-1,
							-1, INT_MAX,
							PGC_SUSET,
							GUC_UNIT_BYTE,
							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_io",
							 "Log I/O statistics.",
							 NULL,
							 &auto_explain_log_io,
							 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);

	DefineCustomStringVariable("auto_explain.log_extension_options",
							   "Extension EXPLAIN options to be added.",
							   NULL,
							   &auto_explain_log_extension_options,
							   NULL,
							   PGC_SUSET,
							   0,
							   check_log_extension_options,
							   assign_log_extension_options,
							   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())
	{
		/* We're always interested in runtime */
		queryDesc->query_instr_options |= INSTRUMENT_TIMER;

		/* 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_io)
				queryDesc->instrument_options |= INSTRUMENT_IO;
			if (auto_explain_log_wal)
				queryDesc->instrument_options |= INSTRUMENT_WAL;
		}
	}

	if (prev_ExecutorStart)
		prev_ExecutorStart(queryDesc, eflags);
	else
		standard_ExecutorStart(queryDesc, eflags);
}

/*
 * ExecutorRun hook: all we need do is track nesting depth
 */
static void
explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction,
					uint64 count)
{
	nesting_level++;
	PG_TRY();
	{
		if (prev_ExecutorRun)
			prev_ExecutorRun(queryDesc, direction, count);
		else
			standard_ExecutorRun(queryDesc, direction, count);
	}
	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->query_instr && 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);

		/* Log plan if duration is exceeded. */
		msec = INSTR_TIME_GET_MILLISEC(queryDesc->query_instr->total);
		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->io = (es->analyze && auto_explain_log_io);
			es->wal = (es->analyze && auto_explain_log_wal);
			es->timing = (es->analyze && auto_explain_log_timing);
			es->summary = es->analyze;
			/* No support for MEMORY */
			/* es->memory = false; */
			es->format = auto_explain_log_format;
			es->settings = auto_explain_log_settings;

			apply_extension_options(es, extension_options);

			ExplainBeginOutput(es);
			ExplainQueryText(es, queryDesc);
			ExplainQueryParameters(es, queryDesc->params, auto_explain_log_parameter_max_length);
			ExplainPrintPlan(es, queryDesc);
			if (es->analyze && auto_explain_log_triggers)
				ExplainPrintTriggers(es, queryDesc);
			if (es->costs)
				ExplainPrintJITSummary(es, queryDesc);
			if (explain_per_plan_hook)
				(*explain_per_plan_hook) (queryDesc->plannedstmt,
										  NULL, es,
										  queryDesc->sourceText,
										  queryDesc->params,
										  queryDesc->estate->es_queryEnv);
			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);
}

/*
 * GUC check hook for auto_explain.log_extension_options.
 */
static bool
check_log_extension_options(char **newval, void **extra, GucSource source)
{
	char	   *rawstring;
	auto_explain_extension_options *result;
	auto_explain_option *options;
	int			maxoptions = 8;
	Size		rawstring_len;
	Size		allocsize;
	char	   *errmsg;

	/* NULL or empty string means no options. */
	if (*newval == NULL || (*newval)[0] == '\0')
	{
		*extra = NULL;
		return true;
	}

	rawstring_len = strlen(*newval) + 1;

retry:
	/* Try to allocate an auto_explain_extension_options object. */
	allocsize = offsetof(auto_explain_extension_options, options) +
		sizeof(auto_explain_option) * maxoptions +
		rawstring_len;
	result = (auto_explain_extension_options *) guc_malloc(LOG, allocsize);
	if (result == NULL)
		return false;

	/* Copy the string after the options array. */
	rawstring = (char *) &result->options[maxoptions];
	memcpy(rawstring, *newval, rawstring_len);

	/* Parse. */
	options = result->options;
	result->noptions = auto_explain_split_options(rawstring, options,
												  maxoptions, &errmsg);
	if (result->noptions < 0)
	{
		GUC_check_errdetail("%s", errmsg);
		guc_free(result);
		return false;
	}

	/*
	 * Retry with a larger array if needed.
	 *
	 * It should be impossible for this to loop more than once, because
	 * auto_explain_split_options tells us how many entries are needed.
	 */
	if (result->noptions > maxoptions)
	{
		maxoptions = result->noptions;
		guc_free(result);
		goto retry;
	}

	/* Validate each option against its registered check handler. */
	for (int i = 0; i < result->noptions; i++)
	{
		if (!GUCCheckExplainExtensionOption(options[i].name, options[i].value,
											options[i].type))
		{
			guc_free(result);
			return false;
		}
	}

	*extra = result;
	return true;
}

/*
 * GUC assign hook for auto_explain.log_extension_options.
 */
static void
assign_log_extension_options(const char *newval, void *extra)
{
	extension_options = (auto_explain_extension_options *) extra;
}

/*
 * Apply parsed extension options to an ExplainState.
 */
static void
apply_extension_options(ExplainState *es, auto_explain_extension_options *ext)
{
	if (ext == NULL)
		return;

	for (int i = 0; i < ext->noptions; i++)
	{
		auto_explain_option *opt = &ext->options[i];
		DefElem    *def;
		Node	   *arg;

		if (opt->value == NULL)
			arg = NULL;
		else if (opt->type == T_Integer)
			arg = (Node *) makeInteger(strtol(opt->value, NULL, 0));
		else if (opt->type == T_Float)
			arg = (Node *) makeFloat(opt->value);
		else
			arg = (Node *) makeString(opt->value);

		def = makeDefElem(opt->name, arg, -1);
		ApplyExtensionExplainOption(es, def, NULL);
	}
}

/*
 * auto_explain_scan_literal - In-place scanner for single-quoted string
 * literals.
 *
 * This is the single-quote analog of scan_quoted_identifier from varlena.c.
 */
static char *
auto_explain_scan_literal(char **endp, char **nextp)
{
	char	   *token = *nextp + 1;

	for (;;)
	{
		*endp = strchr(*nextp + 1, '\'');
		if (*endp == NULL)
			return NULL;		/* mismatched quotes */
		if ((*endp)[1] != '\'')
			break;				/* found end of literal */
		/* Collapse adjacent quotes into one quote, and look again */
		memmove(*endp, *endp + 1, strlen(*endp));
		*nextp = *endp;
	}
	/* *endp now points at the terminating quote */
	*nextp = *endp + 1;

	return token;
}

/*
 * auto_explain_split_options - Parse an option string into an array of
 * auto_explain_option structs.
 *
 * Much of this logic is similar to SplitIdentifierString and friends, but our
 * needs are different enough that we roll our own parsing logic. The goal here
 * is to accept the same syntax that the main parser would accept inside of
 * an EXPLAIN option list. While we can't do that perfectly without adding a
 * lot more code, the goal of this implementation is to be close enough that
 * users don't really notice the differences.
 *
 * The input string is modified in place (null-terminated, downcased, quotes
 * collapsed).  All name and value pointers in the output array refer into
 * this string, so the caller must ensure the string outlives the array.
 *
 * Returns the full number of options in the input string, but stores no
 * more than maxoptions into the caller-provided array. If a syntax error
 * occurs, returns -1 and sets *errmsg.
 */
static int
auto_explain_split_options(char *rawstring, auto_explain_option *options,
						   int maxoptions, char **errmsg)
{
	char	   *nextp = rawstring;
	int			noptions = 0;
	bool		done = false;

	*errmsg = NULL;

	while (scanner_isspace(*nextp))
		nextp++;				/* skip leading whitespace */

	if (*nextp == '\0')
		return 0;				/* empty string is fine */

	while (!done)
	{
		char	   *name;
		char	   *name_endp;
		char	   *value = NULL;
		char	   *value_endp = NULL;
		NodeTag		type = T_Invalid;

		/* Parse the option name. */
		name = scan_identifier(&name_endp, &nextp, ',', true);
		if (name == NULL || name_endp == name)
		{
			*errmsg = "option name missing or empty";
			return -1;
		}

		/* Skip whitespace after the option name. */
		while (scanner_isspace(*nextp))
			nextp++;

		/*
		 * Determine whether we have an option value.  A comma or end of
		 * string means no value; otherwise we have one.
		 */
		if (*nextp != '\0' && *nextp != ',')
		{
			if (*nextp == '\'')
			{
				/* Single-quoted string literal. */
				type = T_String;
				value = auto_explain_scan_literal(&value_endp, &nextp);
				if (value == NULL)
				{
					*errmsg = "unterminated single-quoted string";
					return -1;
				}
			}
			else if (isdigit((unsigned char) *nextp) ||
					 ((*nextp == '+' || *nextp == '-') &&
					  isdigit((unsigned char) nextp[1])))
			{
				char	   *endptr;
				long		intval;
				char		saved;

				/* Remember the start of the next token, and find the end. */
				value = nextp;
				while (*nextp && *nextp != ',' && !scanner_isspace(*nextp))
					nextp++;
				value_endp = nextp;

				/* Temporarily '\0'-terminate so we can use strtol/strtod. */
				saved = *value_endp;
				*value_endp = '\0';

				/*
				 * Integer, float, or neither?
				 *
				 * NB: Since we use strtol and strtod here rather than
				 * pg_strtoint64_safe, some syntax that would be accepted by
				 * the main parser is not accepted here, e.g. 100_000. On the
				 * plus side, strtol and strtod won't allocate, and
				 * pg_strtoint64_safe might. For now, it seems better to keep
				 * things simple here.
				 */
				errno = 0;
				intval = strtol(value, &endptr, 0);
				if (errno == 0 && *endptr == '\0' && endptr != value &&
					intval == (int) intval)
					type = T_Integer;
				else
				{
					type = T_Float;
					(void) strtod(value, &endptr);
					if (*endptr != '\0')
					{
						*value_endp = saved;
						*errmsg = "invalid numeric value";
						return -1;
					}
				}

				/* Remove temporary terminator. */
				*value_endp = saved;
			}
			else
			{
				/* Identifier, possibly double-quoted. */
				type = T_String;
				value = scan_identifier(&value_endp, &nextp, ',', true);
				if (value == NULL)
				{
					/*
					 * scan_identifier will return NULL if it finds an
					 * unterminated double-quoted identifier or it finds no
					 * identifier at all because the next character is
					 * whitespace or the separator character, here a comma.
					 * But the latter case is impossible here because the code
					 * above has skipped whitespace and checked for commas.
					 */
					*errmsg = "unterminated double-quoted string";
					return -1;
				}
			}
		}

		/* Skip trailing whitespace. */
		while (scanner_isspace(*nextp))
			nextp++;

		/* Expect comma or end of string. */
		if (*nextp == ',')
		{
			nextp++;
			while (scanner_isspace(*nextp))
				nextp++;
			if (*nextp == '\0')
			{
				*errmsg = "trailing comma in option list";
				return -1;
			}
		}
		else if (*nextp == '\0')
			done = true;
		else
		{
			*errmsg = "expected comma or end of option list";
			return -1;
		}

		/*
		 * Now safe to null-terminate the name and value.  We couldn't do this
		 * earlier because in the unquoted case, the null terminator position
		 * may coincide with a character that the scanning logic above still
		 * needed to read.
		 */
		*name_endp = '\0';
		if (value_endp != NULL)
			*value_endp = '\0';

		/* Always count this option, and store the details if there is room. */
		if (noptions < maxoptions)
		{
			options[noptions].name = name;
			options[noptions].type = type;
			options[noptions].value = value;
		}
		noptions++;
	}

	return noptions;
}