summaryrefslogtreecommitdiffstats
path: root/contrib/auto_explain/auto_explain.c
diff options
context:
space:
mode:
Diffstat (limited to 'contrib/auto_explain/auto_explain.c')
-rw-r--r--contrib/auto_explain/auto_explain.c429
1 files changed, 429 insertions, 0 deletions
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);
+}
generated by cgit v1.2.3 (git 2.39.1) at 2024-10-31 04:55:37 +0000