diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c index 97ce498d0c1a0..9b523c46bc882 100644 --- a/contrib/auto_explain/auto_explain.c +++ b/contrib/auto_explain/auto_explain.c @@ -16,6 +16,7 @@ #include "access/parallel.h" #include "commands/defrem.h" +#include "commands/dynamic_explain.h" #include "commands/explain.h" #include "commands/explain_format.h" #include "commands/explain_state.h" @@ -451,32 +452,9 @@ explain_ExecutorEnd(QueryDesc *queryDesc) 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] = '}'; - } + ExplainStringAssemble(es, queryDesc, auto_explain_log_format, + auto_explain_log_triggers, + auto_explain_log_parameter_max_length); /* * Note: we rely on the existing logging of context or diff --git a/doc/src/sgml/func/func-admin.sgml b/doc/src/sgml/func/func-admin.sgml index 0eae1c1f61601..ba319c941601b 100644 --- a/doc/src/sgml/func/func-admin.sgml +++ b/doc/src/sgml/func/func-admin.sgml @@ -184,6 +184,30 @@ + + + + pg_log_query_plan + + pg_log_query_plan ( pid integer ) + boolean + + + Requests to log the plan of the query currently running on the + backend with specified process ID. + It will be logged at LOG message level and + will appear in the server log based on the log + configuration set (See + for more information), but will not be sent to the client + regardless of . + + + This function is restricted to superusers by default, but other + users can be granted EXECUTE to run the function. + + + + diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c index 5586fbe5b07c6..d6031f97ca7d5 100644 --- a/src/backend/access/transam/xact.c +++ b/src/backend/access/transam/xact.c @@ -37,6 +37,7 @@ #include "catalog/pg_enum.h" #include "catalog/storage.h" #include "commands/async.h" +#include "commands/dynamic_explain.h" #include "commands/tablecmds.h" #include "commands/trigger.h" #include "common/pg_prng.h" @@ -217,6 +218,7 @@ typedef struct TransactionStateData bool parallelChildXact; /* is any parent transaction parallel? */ bool chain; /* start a new block after this one */ bool topXidLogged; /* for a subxact: is top-level XID logged? */ + QueryDesc *queryDesc; /* my current QueryDesc */ struct TransactionStateData *parent; /* back link to parent */ } TransactionStateData; @@ -250,6 +252,7 @@ static TransactionStateData TopTransactionStateData = { .state = TRANS_DEFAULT, .blockState = TBLOCK_DEFAULT, .topXidLogged = false, + .queryDesc = NULL, }; /* @@ -935,6 +938,27 @@ GetCurrentTransactionNestLevel(void) return s->nestingLevel; } +/* + * SetCurrentQueryDesc + */ +void +SetCurrentQueryDesc(QueryDesc *queryDesc) +{ + TransactionState s = CurrentTransactionState; + + s->queryDesc = queryDesc; +} + +/* + * GetCurrentQueryDesc + */ +QueryDesc * +GetCurrentQueryDesc(void) +{ + TransactionState s = CurrentTransactionState; + + return s->queryDesc; +} /* * TransactionIdIsCurrentTransactionId @@ -2953,6 +2977,9 @@ AbortTransaction(void) /* Reset snapshot export state. */ SnapBuildResetExportedSnapshotState(); + /* Reset current query plan state used for logging. */ + SetCurrentQueryDesc(NULL); + /* * If this xact has started any unfinished parallel operation, clean up * its workers and exit parallel mode. Don't warn about leaked resources. @@ -5352,6 +5379,13 @@ AbortSubTransaction(void) /* Reset logical streaming state. */ ResetLogicalStreamingState(); + /* + * Reset current query plan state used for logging. Note that even after + * this reset, it's still possible to obtain the parent transaction's + * query plans, since they are preserved in standard_ExecutorRun(). + */ + SetCurrentQueryDesc(NULL); + /* * No need for SnapBuildResetExportedSnapshotState() here, snapshot * exports are not supported in subtransactions. diff --git a/src/backend/commands/Makefile b/src/backend/commands/Makefile index 5b9d084977e48..8f13c7f57525a 100644 --- a/src/backend/commands/Makefile +++ b/src/backend/commands/Makefile @@ -31,6 +31,7 @@ OBJS = \ define.o \ discard.o \ dropcmds.o \ + dynamic_explain.o \ event_trigger.o \ explain.o \ explain_dr.o \ diff --git a/src/backend/commands/dynamic_explain.c b/src/backend/commands/dynamic_explain.c new file mode 100644 index 0000000000000..74b4e5a55874c --- /dev/null +++ b/src/backend/commands/dynamic_explain.c @@ -0,0 +1,188 @@ +/*------------------------------------------------------------------------- + * + * dynamic_explain.c + * Explain query plans during execution + * + * Portions Copyright (c) 1996-2025, PostgreSQL Global Development Group + * Portions Copyright (c) 1994-5, Regents of the University of California + * + * IDENTIFICATION + * src/backend/commands/dynamic_explain.c + * + *------------------------------------------------------------------------- + */ +#include "postgres.h" + +#include "access/xact.h" +#include "commands/dynamic_explain.h" +#include "commands/explain.h" +#include "commands/explain_format.h" +#include "commands/explain_state.h" +#include "miscadmin.h" +#include "storage/proc.h" +#include "storage/procarray.h" +#include "storage/procsignal.h" +#include "utils/backend_status.h" +#include "utils/injection_point.h" + +/* Is plan node wrapping for query plan logging currently in progress? */ +static bool WrapNodesInProgress = false; + +/* + * Handle receipt of an interrupt indicating logging the plan of the currently + * running query. + * + * All the actual work is deferred to ProcessLogQueryPlanInterrupt(), + * because we cannot safely emit a log message inside the signal handler. + */ +void +HandleLogQueryPlanInterrupt(void) +{ +#ifdef USE_INJECTION_POINTS + INJECTION_POINT("log-query-interrupt", NULL); +#endif + InterruptPending = true; + LogQueryPlanPending = true; + /* latch will be set by procsignal_sigusr1_handler */ +} + +/* + * Actual plan logging function. + */ +void +LogQueryPlan(void) +{ + ExplainState *es; + MemoryContext cxt; + MemoryContext old_cxt; + QueryDesc *queryDesc; + + cxt = AllocSetContextCreate(CurrentMemoryContext, + "log_query_plan temporary context", + ALLOCSET_DEFAULT_SIZES); + + old_cxt = MemoryContextSwitchTo(cxt); + + es = NewExplainState(); + + es->format = EXPLAIN_FORMAT_TEXT; + es->settings = true; + es->verbose = true; + es->signaled = true; + + /* + * Current QueryDesc is valid only during standard_ExecutorRun. However, + * ExecProcNode can be called afterward(i.e., ExecPostprocessPlan). To + * handle the case, check whether we have QueryDesc now. + */ + queryDesc = GetCurrentQueryDesc(); + + if (queryDesc == NULL) + { + LogQueryPlanPending = false; + return; + } + + ExplainStringAssemble(es, queryDesc, es->format, 0, -1); + + ereport(LOG_SERVER_ONLY, + errmsg("query and its plan running on backend with PID %d are:\n%s", + MyProcPid, es->str->data)); + + MemoryContextSwitchTo(old_cxt); + MemoryContextDelete(cxt); + + LogQueryPlanPending = false; +} + +/* + * Process the request for logging query plan at CHECK_FOR_INTERRUPTS(). + * + * Since executing EXPLAIN-related code at an arbitrary CHECK_FOR_INTERRUPTS() + * point is potentially unsafe, this function just wraps the nodes of + * ExecProcNode with ExecProcNodeFirst, which logs query plan if requested. + * This way ensures that EXPLAIN-related code is executed only during + * ExecProcNodeFirst, where it is considered safe. + */ +void +ProcessLogQueryPlanInterrupt(void) +{ + QueryDesc *querydesc = GetCurrentQueryDesc(); + + /* If current query has already finished, we can do nothing but exit */ + if (querydesc == NULL) + { + LogQueryPlanPending = false; + return; + } + + /* + * Exit immediately if wrapping plan is already in progress. This prevents + * recursive calls, which could occur if logging is requested repeatedly and + * rapidly, potentially leading to infinite recursion and crash. + */ + if (WrapNodesInProgress) + return; + + WrapNodesInProgress = true; + + PG_TRY(); + { + /* + * Wrap ExecProcNodes with ExecProcNodeFirst, which logs query plan + * when LogQueryPlanPending is true. + */ + ExecSetExecProcNodeRecurse(querydesc->planstate); + } + PG_FINALLY(); + { + WrapNodesInProgress = false; + } + PG_END_TRY(); +} + +/* + * Signal a backend process to log the query plan of the running query. + * + * By default, only superusers are allowed to signal to log the plan because + * allowing any users to issue this request at an unbounded rate would + * cause lots of log messages and which can lead to denial of service. + * Additional roles can be permitted with GRANT. + */ +Datum +pg_log_query_plan(PG_FUNCTION_ARGS) +{ + int pid = PG_GETARG_INT32(0); + PGPROC *proc; + PgBackendStatus *be_status; + + proc = BackendPidGetProc(pid); + + if (proc == NULL) + { + /* + * This is just a warning so a loop-through-resultset will not abort + * if one backend terminated on its own during the run. + */ + ereport(WARNING, + (errmsg("PID %d is not a PostgreSQL backend process", pid))); + PG_RETURN_BOOL(false); + } + + be_status = pgstat_get_beentry_by_proc_number(proc->vxid.procNumber); + if (be_status->st_backendType != B_BACKEND) + { + ereport(WARNING, + (errmsg("PID %d is not a PostgreSQL client backend process", pid))); + PG_RETURN_BOOL(false); + } + + if (SendProcSignal(pid, PROCSIG_LOG_QUERY_PLAN, proc->vxid.procNumber) < 0) + { + ereport(WARNING, + (errmsg("could not send signal to process %d: %m", pid))); + PG_RETURN_BOOL(false); + } + + PG_RETURN_BOOL(true); +} diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 112c17b0d6428..51648b5d51097 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -1092,6 +1092,43 @@ ExplainQueryParameters(ExplainState *es, ParamListInfo params, int maxlen) ExplainPropertyText("Query Parameters", str, es); } +/* + * ExplainStringAssemble - + * Assemble es->str for logging according to specified options and format + */ + +void +ExplainStringAssemble(ExplainState *es, QueryDesc *queryDesc, int logFormat, + bool logTriggers, int logParameterMaxLength) +{ + ExplainBeginOutput(es); + ExplainQueryText(es, queryDesc); + ExplainQueryParameters(es, queryDesc->params, logParameterMaxLength); + ExplainPrintPlan(es, queryDesc); + if (es->analyze && logTriggers) + 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 (logFormat == EXPLAIN_FORMAT_JSON) + { + es->str->data[0] = '{'; + es->str->data[es->str->len - 1] = '}'; + } +} + /* * report_triggers - * report execution stats for a single relation's triggers @@ -1827,7 +1864,10 @@ ExplainNode(PlanState *planstate, List *ancestors, /* * We have to forcibly clean up the instrumentation state because we - * haven't done ExecutorEnd yet. This is pretty grotty ... + * haven't done ExecutorEnd yet. This is pretty grotty ... This cleanup + * should not be done when the query has already been executed and explain + * has been requested by signal, as the target query may use + * instrumentation and clean itself up. * * Note: contrib/auto_explain could cause instrumentation to be set up * even though we didn't ask for it here. Be careful not to print any @@ -1835,7 +1875,7 @@ ExplainNode(PlanState *planstate, List *ancestors, * InstrEndLoop call anyway, if possible, to reduce the number of cases * auto_explain has to contend with. */ - if (planstate->instrument) + if (planstate->instrument && !es->signaled) InstrEndLoop(planstate->instrument); if (es->analyze && diff --git a/src/backend/commands/meson.build b/src/backend/commands/meson.build index 9f258d566ebf6..2f2b30cea0cd2 100644 --- a/src/backend/commands/meson.build +++ b/src/backend/commands/meson.build @@ -19,6 +19,7 @@ backend_sources += files( 'define.c', 'discard.c', 'dropcmds.c', + 'dynamic_explain.c', 'event_trigger.c', 'explain.c', 'explain_dr.c', diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c index 4b30f7686801a..c749cae8008a8 100644 --- a/src/backend/executor/execMain.c +++ b/src/backend/executor/execMain.c @@ -44,6 +44,7 @@ #include "access/xact.h" #include "catalog/namespace.h" #include "catalog/partition.h" +#include "commands/dynamic_explain.h" #include "commands/matview.h" #include "commands/trigger.h" #include "executor/executor.h" @@ -323,6 +324,7 @@ standard_ExecutorRun(QueryDesc *queryDesc, DestReceiver *dest; bool sendTuples; MemoryContext oldcontext; + QueryDesc *oldQueryDesc; /* sanity checks */ Assert(queryDesc != NULL); @@ -335,6 +337,13 @@ standard_ExecutorRun(QueryDesc *queryDesc, /* caller must ensure the query's snapshot is active */ Assert(GetActiveSnapshot() == estate->es_snapshot); + /* + * Save current QueryDesc here to enable retrieval of the currently + * running queryDesc for nested queries. + */ + oldQueryDesc = GetCurrentQueryDesc(); + SetCurrentQueryDesc(queryDesc); + /* * Switch into per-query memory context */ @@ -397,6 +406,14 @@ standard_ExecutorRun(QueryDesc *queryDesc, InstrStop(queryDesc->query_instr); MemoryContextSwitchTo(oldcontext); + SetCurrentQueryDesc(oldQueryDesc); + + /* + * Ensure LogQueryPlanPending is initialized in case there was no time for + * logging the plan. Othewise plan will be logged at the next query + * execution on the same session. + */ + LogQueryPlanPending = false; } /* ---------------------------------------------------------------- diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c index 7c4c66e323fed..25e5541eecda8 100644 --- a/src/backend/executor/execProcnode.c +++ b/src/backend/executor/execProcnode.c @@ -72,6 +72,7 @@ */ #include "postgres.h" +#include "commands/dynamic_explain.h" #include "executor/executor.h" #include "executor/instrument.h" #include "executor/nodeAgg.h" @@ -431,9 +432,10 @@ ExecSetExecProcNode(PlanState *node, ExecProcNodeMtd function) { /* * Add a wrapper around the ExecProcNode callback that checks stack depth - * during the first execution and maybe adds an instrumentation wrapper. - * When the callback is changed after execution has already begun that - * means we'll superfluously execute ExecProcNodeFirst, but that seems ok. + * and query logging request during the execution and maybe adds an + * instrumentation wrapper. When the callback is changed after execution + * has already begun that means we'll superfluously execute + * ExecProcNodeFirst, but that seems ok. */ node->ExecProcNodeReal = function; node->ExecProcNode = ExecProcNodeFirst; @@ -441,27 +443,43 @@ ExecSetExecProcNode(PlanState *node, ExecProcNodeMtd function) /* - * ExecProcNode wrapper that performs some one-time checks, before calling + * ExecProcNode wrapper that performs some extra checks, before calling * the relevant node method (possibly via an instrumentation wrapper). + * + * Normally, this is just invoked once for the first call to any given node, + * and thereafter we arrange to call ExecProcNodeInstr or the relevant node + * method directly. However, it's legal to reset node->ExecProcNode back to + * this function at any time, and we do that whenever the query plan might + * need to be printed, so that we only incur the cost of checking for that + * case when required. */ static TupleTableSlot * ExecProcNodeFirst(PlanState *node) { /* - * Perform stack depth check during the first execution of the node. We - * only do so the first time round because it turns out to not be cheap on - * some common architectures (eg. x86). This relies on the assumption - * that ExecProcNode calls for a given plan node will always be made at - * roughly the same stack depth. + * Perform a stack depth check. We don't want to do this all the time + * because it turns out to not be cheap on some common architectures (eg. + * x86). This relies on the assumption that ExecProcNode calls for a + * given plan node will always be made at roughly the same stack depth. */ check_stack_depth(); + /* + * If we have been asked to print the query plan, do that now. We dare not + * try to do this directly from CHECK_FOR_INTERRUPTS() because we don't + * really know what the executor state is at that point, but we assume + * that when entering a node the state will be sufficiently consistent + * that trying to print the plan makes sense. + */ + if (LogQueryPlanPending) + LogQueryPlan(); + /* * If instrumentation is required, change the wrapper to one that just * does instrumentation. Otherwise we can dispense with all wrappers and * have ExecProcNode() directly call the relevant function from now on. */ - if (node->instrument) + else if (node->instrument) node->ExecProcNode = ExecProcNodeInstr; else node->ExecProcNode = node->ExecProcNodeReal; @@ -527,6 +545,91 @@ MultiExecProcNode(PlanState *node) return result; } +/* + * Wrap array of PlanState ExecProcNode with ExecProcNodeFirst. + */ +static void +ExecSetExecProcNodeArray(PlanState **planstates, int nplans) +{ + int i; + + for (i = 0; i < nplans; i++) + ExecSetExecProcNodeRecurse(planstates[i]); +} + +/* + * Wrap CustomScanState children's ExecProcNode with ExecProcNodeFirst. + */ +static void +CSSChildExecSetExecProcNodeArray(CustomScanState *css) +{ + ListCell *cell; + + foreach(cell, css->custom_ps) + ExecSetExecProcNodeRecurse((PlanState *) lfirst(cell)); +} + +/* + * Recursively wrap all the underlying ExecProcNode with ExecProcNodeFirst. + * + * Recursion is usually necessary because the next ExecProcNode() call may be + * invoked not only through the current node, but also via lefttree, righttree, + * subPlan, or other special child plans. + */ +void +ExecSetExecProcNodeRecurse(PlanState *ps) +{ + ExecSetExecProcNode(ps, ps->ExecProcNodeReal); + + if (ps->lefttree != NULL) + ExecSetExecProcNodeRecurse(ps->lefttree); + if (ps->righttree != NULL) + ExecSetExecProcNodeRecurse(ps->righttree); + if (ps->subPlan != NULL) + { + ListCell *l; + + foreach(l, ps->subPlan) + { + SubPlanState *sstate = (SubPlanState *) lfirst(l); + + ExecSetExecProcNodeRecurse(sstate->planstate); + } + } + + /* special child plans */ + switch (nodeTag(ps->plan)) + { + case T_Append: + ExecSetExecProcNodeArray(((AppendState *) ps)->appendplans, + ((AppendState *) ps)->as_nplans); + break; + case T_MergeAppend: + ExecSetExecProcNodeArray(((MergeAppendState *) ps)->mergeplans, + ((MergeAppendState *) ps)->ms_nplans); + break; + case T_BitmapAnd: + ExecSetExecProcNodeArray(((BitmapAndState *) ps)->bitmapplans, + ((BitmapAndState *) ps)->nplans); + break; + case T_BitmapOr: + ExecSetExecProcNodeArray(((BitmapOrState *) ps)->bitmapplans, + ((BitmapOrState *) ps)->nplans); + break; + case T_SubqueryScan: + ExecSetExecProcNodeRecurse(((SubqueryScanState *) ps)->subplan); + break; + case T_CteScan: + ExecSetExecProcNodeRecurse(((CteScanState *) ps)->cteplanstate); + break; + case T_CustomScan: + CSSChildExecSetExecProcNodeArray((CustomScanState *) ps); + break; + default: + break; + } +} + /* ---------------------------------------------------------------- * ExecEndNode diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c index 1397f65f67b6d..bb01f605d00c2 100644 --- a/src/backend/storage/ipc/procsignal.c +++ b/src/backend/storage/ipc/procsignal.c @@ -19,6 +19,7 @@ #include "access/parallel.h" #include "commands/async.h" +#include "commands/dynamic_explain.h" #include "commands/repack.h" #include "miscadmin.h" #include "pgstat.h" @@ -713,6 +714,9 @@ procsignal_sigusr1_handler(SIGNAL_ARGS) if (CheckProcSignal(PROCSIG_LOG_MEMORY_CONTEXT)) HandleLogMemoryContextInterrupt(); + if (CheckProcSignal(PROCSIG_LOG_QUERY_PLAN)) + HandleLogQueryPlanInterrupt(); + if (CheckProcSignal(PROCSIG_PARALLEL_APPLY_MESSAGE)) HandleParallelApplyMessageInterrupt(); diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index dbef734a93f15..98413ad58fdcf 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -36,6 +36,7 @@ #include "access/xact.h" #include "catalog/pg_type.h" #include "commands/async.h" +#include "commands/dynamic_explain.h" #include "commands/event_trigger.h" #include "commands/explain_state.h" #include "commands/prepare.h" @@ -3609,6 +3610,9 @@ ProcessInterrupts(void) if (LogMemoryContextPending) ProcessLogMemoryContextInterrupt(); + if (LogQueryPlanPending) + ProcessLogQueryPlanInterrupt(); + if (ParallelApplyMessagePending) ProcessParallelApplyMessages(); diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c index bbd28d14d9948..de84fd9cfa301 100644 --- a/src/backend/utils/init/globals.c +++ b/src/backend/utils/init/globals.c @@ -40,6 +40,8 @@ volatile sig_atomic_t IdleSessionTimeoutPending = false; volatile sig_atomic_t ProcSignalBarrierPending = false; volatile sig_atomic_t LogMemoryContextPending = false; volatile sig_atomic_t IdleStatsUpdateTimeoutPending = false; +volatile sig_atomic_t LogQueryPlanPending = false; + volatile uint32 InterruptHoldoffCount = 0; volatile uint32 QueryCancelHoldoffCount = 0; volatile uint32 CritSectionCount = 0; diff --git a/src/include/access/xact.h b/src/include/access/xact.h index a8cbdf247c866..f2881d956c005 100644 --- a/src/include/access/xact.h +++ b/src/include/access/xact.h @@ -432,6 +432,7 @@ typedef struct xl_xact_parsed_abort TimestampTz origin_timestamp; } xl_xact_parsed_abort; +typedef struct QueryDesc QueryDesc; /* ---------------- * extern definitions @@ -458,6 +459,8 @@ extern TimestampTz GetCurrentStatementStartTimestamp(void); extern TimestampTz GetCurrentTransactionStopTimestamp(void); extern void SetCurrentStatementStartTimestamp(void); extern int GetCurrentTransactionNestLevel(void); +QueryDesc *GetCurrentQueryDesc(void); +void SetCurrentQueryDesc(QueryDesc *queryDesc); extern bool TransactionIdIsCurrentTransactionId(TransactionId xid); extern int GetTopReadOnlyTransactionNestLevel(void); extern void CommandCounterIncrement(void); diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index be157a5fbe90c..92976b1e53271 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -8721,6 +8721,13 @@ prorettype => 'bool', proargtypes => 'int4', prosrc => 'pg_log_backend_memory_contexts', proacl => '{POSTGRES=X}' }, +# logging plan of the running query on the specified backend +{ oid => '8000', descr => 'log plan of the running query on the specified backend', + proname => 'pg_log_query_plan', + provolatile => 'v', prorettype => 'bool', + proargtypes => 'int4', prosrc => 'pg_log_query_plan', + proacl => '{POSTGRES=X}' }, + # non-persistent series generator { oid => '1066', descr => 'non-persistent series generator', proname => 'generate_series', prorows => '1000', diff --git a/src/include/commands/dynamic_explain.h b/src/include/commands/dynamic_explain.h new file mode 100644 index 0000000000000..83a9e27deef91 --- /dev/null +++ b/src/include/commands/dynamic_explain.h @@ -0,0 +1,25 @@ +/*------------------------------------------------------------------------- + * + * dynamic_explain.h + * prototypes for dynamic_explain.c + * + * Portions Copyright (c) 1996-2025, PostgreSQL Global Development Group + * Portions Copyright (c) 1994-5, Regents of the University of California + * + * src/include/commands/dynamic_explain.h + * + *------------------------------------------------------------------------- + */ +#ifndef DYNAMIC_EXPLAIN_H +#define DYNAMIC_EXPLAIN_H + +#include "executor/executor.h" +#include "commands/explain_state.h" + +extern void HandleLogQueryPlanInterrupt(void); +extern void ProcessLogQueryPlanInterrupt(void); +extern TupleTableSlot *ExecProcNodeWithExplain(PlanState *ps); +extern void LogQueryPlan(void); +extern Datum pg_log_query_plan(PG_FUNCTION_ARGS); + +#endif /* DYNAMIC_EXPLAIN_H */ diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h index 472e141bba3ff..0186e01df1c73 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -71,8 +71,10 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, const BufferUsage *bufusage, const MemoryContextCounters *mem_counters); -extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc); -extern void ExplainPrintTriggers(ExplainState *es, +extern void ExplainPrintPlan(struct ExplainState *es, QueryDesc *queryDesc); +extern void ExplainPrintTriggers(struct ExplainState *es, QueryDesc *queryDesc); +extern void ExplainPrintPlan(struct ExplainState *es, QueryDesc *queryDesc); +extern void ExplainPrintTriggers(struct ExplainState *es, QueryDesc *queryDesc); extern void ExplainPrintJITSummary(ExplainState *es, @@ -81,5 +83,8 @@ extern void ExplainPrintJITSummary(ExplainState *es, extern void ExplainQueryText(ExplainState *es, QueryDesc *queryDesc); extern void ExplainQueryParameters(ExplainState *es, ParamListInfo params, int maxlen); +extern void ExplainStringAssemble(struct ExplainState *es, QueryDesc *queryDesc, + int logFormat, bool logTriggers, + int logParameterMaxLength); #endif /* EXPLAIN_H */ diff --git a/src/include/commands/explain_state.h b/src/include/commands/explain_state.h index 97bc7ed49f66b..b9a9815781527 100644 --- a/src/include/commands/explain_state.h +++ b/src/include/commands/explain_state.h @@ -73,6 +73,7 @@ typedef struct ExplainState * entry */ /* state related to the current plan node */ ExplainWorkersState *workers_state; /* needed if parallel plan */ + bool signaled; /* whether explain is called by signal */ /* extensions */ void **extension_state; int extension_state_allocated; diff --git a/src/include/executor/executor.h b/src/include/executor/executor.h index 33bbdbfeffb50..777922d3846d0 100644 --- a/src/include/executor/executor.h +++ b/src/include/executor/executor.h @@ -299,6 +299,7 @@ extern void EvalPlanQualEnd(EPQState *epqstate); extern PlanState *ExecInitNode(Plan *node, EState *estate, int eflags); extern void ExecSetExecProcNode(PlanState *node, ExecProcNodeMtd function); extern Node *MultiExecProcNode(PlanState *node); +extern void ExecSetExecProcNodeRecurse(PlanState *ps); extern void ExecEndNode(PlanState *node); extern void ExecShutdownNode(PlanState *node); extern void ExecSetTupleBound(int64 tuples_needed, PlanState *child_node); diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h index 7de0a11540236..2374a0079df29 100644 --- a/src/include/miscadmin.h +++ b/src/include/miscadmin.h @@ -98,6 +98,7 @@ extern PGDLLIMPORT volatile sig_atomic_t IdleSessionTimeoutPending; extern PGDLLIMPORT volatile sig_atomic_t ProcSignalBarrierPending; extern PGDLLIMPORT volatile sig_atomic_t LogMemoryContextPending; extern PGDLLIMPORT volatile sig_atomic_t IdleStatsUpdateTimeoutPending; +extern PGDLLIMPORT volatile sig_atomic_t LogQueryPlanPending; extern PGDLLIMPORT volatile sig_atomic_t CheckClientConnectionPending; extern PGDLLIMPORT volatile sig_atomic_t ClientConnectionLost; diff --git a/src/include/storage/procsignal.h b/src/include/storage/procsignal.h index aaa158bfd6618..c2142043e2d1e 100644 --- a/src/include/storage/procsignal.h +++ b/src/include/storage/procsignal.h @@ -35,6 +35,8 @@ typedef enum PROCSIG_WALSND_INIT_STOPPING, /* ask walsenders to prepare for shutdown */ PROCSIG_BARRIER, /* global barrier interrupt */ PROCSIG_LOG_MEMORY_CONTEXT, /* ask backend to log the memory contexts */ + PROCSIG_LOG_QUERY_PLAN, /* ask backend to log plan of the current + * query */ PROCSIG_PARALLEL_APPLY_MESSAGE, /* Message from parallel apply workers */ PROCSIG_SLOTSYNC_MESSAGE, /* ask slot synchronization to stop */ PROCSIG_REPACK_MESSAGE, /* Message from repack worker */ diff --git a/src/test/modules/test_misc/meson.build b/src/test/modules/test_misc/meson.build index 969e90b396da0..4c23bb794c728 100644 --- a/src/test/modules/test_misc/meson.build +++ b/src/test/modules/test_misc/meson.build @@ -22,6 +22,7 @@ tests += { 't/011_lock_stats.pl', 't/012_ddlutils.pl', 't/013_temp_obj_multisession.pl', + 't/014_pg_log_query_plan.pl', ], # The injection points are cluster-wide, so disable installcheck 'runningcheck': false, diff --git a/src/test/modules/test_misc/t/014_pg_log_query_plan.pl b/src/test/modules/test_misc/t/014_pg_log_query_plan.pl new file mode 100644 index 0000000000000..817ff3a1dcdb4 --- /dev/null +++ b/src/test/modules/test_misc/t/014_pg_log_query_plan.pl @@ -0,0 +1,101 @@ + +# Copyright (c) 2024-2025, PostgreSQL Global Development Group + +use strict; +use warnings FATAL => 'all'; +use locale; + +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +# Test that pg_log_query_plan() actually logs the query plan of +# another backend executing a query. + +# This test requires timing cordinations: +# 1) The target backend must be executing a query when +# pg_log_query_plan() sends the signal. +# 2) We must confirm that the target backend actually received the +# signal that requests logging of the plan. +# +# We use an advisory lock and an injection point to control them +# respectively. + +if ($ENV{enable_injection_points} ne 'yes') +{ + plan skip_all => 'Injection points not supported by this build'; +} + +# Node initialization +my $node = PostgreSQL::Test::Cluster->new('node'); +$node->init(); +$node->start; + +# Check if the extension injection_points is available, as it may be +# possible that this script is run with installcheck, where the module +# would not be installed by default. +if (!$node->check_extension('injection_points')) +{ + plan skip_all => 'Extension injection_points not installed'; +} + +$node->safe_psql('postgres', 'CREATE EXTENSION injection_points;'); + +my $psql_session1 = $node->background_psql('postgres'); +my $psql_session2 = $node->background_psql('postgres'); + +my $session1_pid = $psql_session1->query_safe("select pg_backend_pid()"); + +# Set injection point in the logging plan request handler to ensure +# that session1 received the signal of pg_log_query_plan(). +$psql_session1->query_safe( + qq[ + SELECT injection_points_set_local(); + SELECT injection_points_attach('log-query-interrupt', 'wait'); +]); + +# Use an advisory lock to make session1 blocked during query execution. +$psql_session2->query_safe( + qq[ + BEGIN; + SELECT pg_advisory_xact_lock(1); +]); + +$psql_session1->query_until( + qr/wait_on_advisory_lock/, q( + \echo wait_on_advisory_lock + BEGIN; + SELECT pg_advisory_xact_lock(1); +)); + +# Confirm that session1 is actually waiting on the advisory lock. +$node->wait_for_event('client backend', 'advisory'); + +# Run pg_log_query_plan(). +$psql_session2->query_safe("SELECT pg_log_query_plan($session1_pid);"); + +# Ensure that the signal of pg_log_query_plan() is actually +# rececived by confirming session1 is waiting on the injection point. +$node->wait_for_event('client backend', 'log-query-interrupt'); + +# Commit the session 2 to release the advisory lock. +$psql_session2->query_safe("COMMIT;"); + +my $log_offset = -s $node->logfile; + +# Detach the injection point to start logging the plan. +$psql_session2->query_safe( + qq[ + SELECT injection_points_wakeup('log-query-interrupt'); + SELECT injection_points_detach('log-query-interrupt'); +]); + +$node->wait_for_log('query and its plan running on backend with PID', + $log_offset); + +$psql_session1->query_safe("COMMIT;"); + +ok($psql_session1->quit); +ok($psql_session2->quit); + +done_testing(); diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out index c3261bff209fb..5d310939a7543 100644 --- a/src/test/regress/expected/misc_functions.out +++ b/src/test/regress/expected/misc_functions.out @@ -357,6 +357,44 @@ REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer) FROM regress_log_memory; DROP ROLE regress_log_memory; -- +-- pg_log_query_plan() +-- +-- Plans are logged and they are not returned to the function. +-- Furthermore, their contents can vary depending on the optimizer. +-- Here we just verifies that the permissions are set properly. +-- +-- The test that verifies the backend's query plan is actually +-- logged is implemented in +-- src/test/modules/test_misc/t/009_pg_log_query_plan.pl. +CREATE ROLE regress_log_plan; +SELECT has_function_privilege('regress_log_plan', + 'pg_log_query_plan(integer)', 'EXECUTE'); -- no + has_function_privilege +------------------------ + f +(1 row) + +GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer) + TO regress_log_plan; +SELECT has_function_privilege('regress_log_plan', + 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes + has_function_privilege +------------------------ + t +(1 row) + +SET ROLE regress_log_plan; +SELECT pg_log_query_plan(pg_backend_pid()); + pg_log_query_plan +------------------- + t +(1 row) + +RESET ROLE; +REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer) + FROM regress_log_plan; +DROP ROLE regress_log_plan; +-- -- Test some built-in SRFs -- -- The outputs of these are variable, so we can't just print their results diff --git a/src/test/regress/sql/misc_functions.sql b/src/test/regress/sql/misc_functions.sql index 946ee5726cdd7..e7ab81cca6007 100644 --- a/src/test/regress/sql/misc_functions.sql +++ b/src/test/regress/sql/misc_functions.sql @@ -113,6 +113,37 @@ REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer) DROP ROLE regress_log_memory; +-- +-- pg_log_query_plan() +-- +-- Plans are logged and they are not returned to the function. +-- Furthermore, their contents can vary depending on the optimizer. +-- Here we just verifies that the permissions are set properly. +-- +-- The test that verifies the backend's query plan is actually +-- logged is implemented in +-- src/test/modules/test_misc/t/009_pg_log_query_plan.pl. + +CREATE ROLE regress_log_plan; + +SELECT has_function_privilege('regress_log_plan', + 'pg_log_query_plan(integer)', 'EXECUTE'); -- no + +GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer) + TO regress_log_plan; + +SELECT has_function_privilege('regress_log_plan', + 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes + +SET ROLE regress_log_plan; +SELECT pg_log_query_plan(pg_backend_pid()); +RESET ROLE; + +REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer) + FROM regress_log_plan; + +DROP ROLE regress_log_plan; + -- -- Test some built-in SRFs --