From a374bf485e6e7237314179313ac7cb61a0ad784b Mon Sep 17 00:00:00 2001 From: Atsushi Torikoshi Date: Wed, 13 Mar 2024 13:47:18 +0900 Subject: [PATCH v38] Add function to log the plan of the query Currently, we have to wait for the query execution to finish to check its plan. This is not so convenient when investigating long-running queries on production environments where we cannot use debuggers. To improve this situation, this patch adds pg_log_query_plan() function that requests to log the plan of the specified backend process. By default, only superusers are allowed to request to log the plans 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. On receipt of the request, EXPLAIN codes for logging is wrapped to every ExecProcNode and when the executor runs one of ExecProcNode, the plan is logged. These EXPLAIN codes are unwrapped when EXPLAIN codes actually run once. In this way, we can avoid adding the overhead which we'll face when adding CHECK_FOR_INTERRUPTS() like mechanisms in somewhere in executor codes. --- contrib/auto_explain/Makefile | 2 + contrib/auto_explain/auto_explain.c | 23 +- contrib/auto_explain/t/001_auto_explain.pl | 35 +++ doc/src/sgml/func.sgml | 50 ++++ src/backend/access/transam/xact.c | 17 ++ src/backend/catalog/system_functions.sql | 2 + src/backend/commands/explain.c | 228 +++++++++++++++++- src/backend/executor/execMain.c | 19 ++ src/backend/storage/ipc/procsignal.c | 4 + src/backend/tcop/postgres.c | 4 + src/backend/utils/init/globals.c | 2 + src/include/catalog/pg_proc.dat | 6 + src/include/commands/explain.h | 9 + src/include/miscadmin.h | 1 + src/include/nodes/execnodes.h | 3 + src/include/storage/procsignal.h | 1 + src/include/tcop/pquery.h | 2 +- src/include/utils/elog.h | 1 + .../injection_points/injection_points.c | 11 + src/test/regress/expected/misc_functions.out | 54 ++++- src/test/regress/sql/misc_functions.sql | 41 +++- 21 files changed, 473 insertions(+), 42 deletions(-) diff --git a/contrib/auto_explain/Makefile b/contrib/auto_explain/Makefile index efd127d3ca..64fe0e0573 100644 --- a/contrib/auto_explain/Makefile +++ b/contrib/auto_explain/Makefile @@ -8,6 +8,8 @@ PGFILEDESC = "auto_explain - logging facility for execution plans" TAP_TESTS = 1 +EXTRA_INSTALL = src/test/modules/injection_points + ifdef USE_PGXS PG_CONFIG = pg_config PGXS := $(shell $(PG_CONFIG) --pgxs) diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c index 677c135f59..e041b10b0e 100644 --- a/contrib/auto_explain/auto_explain.c +++ b/contrib/auto_explain/auto_explain.c @@ -401,26 +401,9 @@ explain_ExecutorEnd(QueryDesc *queryDesc) es->format = auto_explain_log_format; es->settings = auto_explain_log_settings; - 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); - 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] = '}'; - } + ExplainAssembleLogOutput(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/contrib/auto_explain/t/001_auto_explain.pl b/contrib/auto_explain/t/001_auto_explain.pl index 0e5b34afa9..36a787174e 100644 --- a/contrib/auto_explain/t/001_auto_explain.pl +++ b/contrib/auto_explain/t/001_auto_explain.pl @@ -35,6 +35,8 @@ $node->append_conf('postgresql.conf', "auto_explain.log_min_duration = 0"); $node->append_conf('postgresql.conf', "auto_explain.log_analyze = on"); $node->start; +$node->safe_psql('postgres', 'CREATE EXTENSION injection_points'); + # Simple query. my $log_contents = query_log($node, "SELECT * FROM pg_class;"); @@ -212,4 +214,37 @@ REVOKE SET ON PARAMETER auto_explain.log_format FROM regress_user1; DROP USER regress_user1; }); +# Check that using both auto_explain and pg_log_query_plan() works fine + +$node->safe_psql('postgres', q{SELECT injection_points_attach('executor-run', 'logqueryplan')}); + +$log_contents = query_log( + $node, + "SELECT * FROM pg_class;", + { + "auto_explain.log_verbose" => "on", + "auto_explain.log_settings" => "on", + "auto_explain.log_analyze" => "off", + "compute_query_id" => "on" + }); + +like( + $log_contents, + qr/query plan running on backend with PID/, + "with pg_log_query_plan(), pg_log_query_plan() logged"); + +like( + $log_contents, + qr/duration: .+ms plan:/, + "with pg_log_query_plan(), auto_explain logged"); + +$log_contents =~ /(Query Text:.*Query Identifier: \d+).*(Query Text:.*Query Identifier: \d+)/s; +my $pg_log_plan_query_output = $1; +my $auto_explain_output = $2; + +cmp_ok( + $pg_log_plan_query_output, "eq", + $auto_explain_output, + "with pg_log_plan_query_log(), logged plans are the same"); + done_testing(); diff --git a/doc/src/sgml/func.sgml b/doc/src/sgml/func.sgml index 0bb7aeb40e..6f4285e18d 100644 --- a/doc/src/sgml/func.sgml +++ b/doc/src/sgml/func.sgml @@ -27195,6 +27195,25 @@ SELECT collation for ('foo' COLLATE "de_DE"); + + + + 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 . + + + @@ -27309,6 +27328,37 @@ LOG: Grand total: 1651920 bytes in 201 blocks; 622360 free (88 chunks); 1029560 because it may generate a large number of log messages. + + pg_log_query_plan can be used + to log the plan of a backend process. For example: + +postgres=# SELECT pg_log_query_plan(201116); + pg_log_query_plan +--------------------------- + t +(1 row) + +The format of the query plan is the same as when VERBOSE, +COSTS, SETTINGS and +FORMAT TEXT are used in the EXPLAIN +command. For example: + +LOG: query plan running on backend with PID 201116 is: + Query Text: SELECT * FROM pgbench_accounts; + Seq Scan on public.pgbench_accounts (cost=0.00..52787.00 rows=2000000 width=97) + Output: aid, bid, abalance, filler + Settings: work_mem = '1MB' + Query Identifier: 8621255546560739680 + + Note that when statements are executed inside a function, only the + plan of the most deeply nested query is logged. + + + + When a subtransaction is aborted, pg_log_query_plan + cannot log the query plan after the abort. + + diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c index 1d930752c5..ac6682768c 100644 --- a/src/backend/access/transam/xact.c +++ b/src/backend/access/transam/xact.c @@ -60,6 +60,7 @@ #include "storage/procarray.h" #include "storage/sinvaladt.h" #include "storage/smgr.h" +#include "tcop/pquery.h" #include "utils/builtins.h" #include "utils/combocid.h" #include "utils/guc.h" @@ -2768,6 +2769,14 @@ AbortTransaction(void) */ sigprocmask(SIG_SETMASK, &UnBlockSig, NULL); + /* + * Reset pg_log_query_plan() related global variables. + * When ActiveQueryDesc is referenced after abort, some of its elements + * are freed. To avoid accessing them, reset ActiveQueryDesc here. + */ + ActiveQueryDesc = NULL; + ProcessLogQueryPlanInterruptActive = false; + /* * check the current transaction state */ @@ -5185,6 +5194,14 @@ AbortSubTransaction(void) */ sigprocmask(SIG_SETMASK, &UnBlockSig, NULL); + /* + * Reset pg_log_query_plan() related global variables. + * When ActiveQueryDesc is referenced after abort, some of its elements + * are freed. To avoid accessing them, reset ActiveQueryDesc here. + */ + ActiveQueryDesc = NULL; + ProcessLogQueryPlanInterruptActive = false; + /* * check the current transaction state */ diff --git a/src/backend/catalog/system_functions.sql b/src/backend/catalog/system_functions.sql index fe2bb50f46..2e50b596cd 100644 --- a/src/backend/catalog/system_functions.sql +++ b/src/backend/catalog/system_functions.sql @@ -757,6 +757,8 @@ REVOKE EXECUTE ON FUNCTION pg_ls_logicalmapdir() FROM PUBLIC; REVOKE EXECUTE ON FUNCTION pg_ls_replslotdir(text) FROM PUBLIC; +REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer) FROM PUBLIC; + -- -- We also set up some things as accessible to standard roles. -- diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index a9d5056af4..12c2052dec 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -20,6 +20,7 @@ #include "commands/prepare.h" #include "foreign/fdwapi.h" #include "jit/jit.h" +#include "miscadmin.h" #include "nodes/extensible.h" #include "nodes/makefuncs.h" #include "nodes/nodeFuncs.h" @@ -27,7 +28,10 @@ #include "parser/parsetree.h" #include "rewrite/rewriteHandler.h" #include "storage/bufmgr.h" +#include "storage/procarray.h" +#include "tcop/pquery.h" #include "tcop/tcopprot.h" +#include "utils/backend_status.h" #include "utils/builtins.h" #include "utils/guc_tables.h" #include "utils/json.h" @@ -39,6 +43,7 @@ #include "utils/typcache.h" #include "utils/xml.h" +bool ProcessLogQueryPlanInterruptActive = false; /* Hook for plugins to get control in ExplainOneQuery() */ ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL; @@ -154,6 +159,9 @@ static void ExplainIndentText(ExplainState *es); static void ExplainJSONLineEnding(ExplainState *es); static void ExplainYAMLLineStarting(ExplainState *es); static void escape_yaml(StringInfo buf, const char *str); +static void WrapExecProcNodeWithExplain(PlanState *ps); +static void UnWrapExecProcNodeWithExplain(PlanState *ps); +static TupleTableSlot *ExecProcNodeWithExplain(PlanState *ps); @@ -795,6 +803,37 @@ ExplainPrintSettings(ExplainState *es) } } +/* + * ExplainAssembleLogOutput - + * Assemble es->str for logging according to specified contents and format + */ + +void +ExplainAssembleLogOutput(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); + 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] = '}'; + } +} + /* * ExplainPrintPlan - * convert a QueryDesc's plan tree to text and append it to es->str @@ -1705,6 +1744,9 @@ 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 ... + * This cleanup should not be done when the query has already been + * executed and explain has been called 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 @@ -1712,7 +1754,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 && @@ -5193,3 +5235,187 @@ escape_yaml(StringInfo buf, const char *str) { escape_json(buf, str); } + +/* + * HandleLogQueryPlanInterrupt + * 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) +{ + InterruptPending = true; + LogQueryPlanPending = true; + /* latch will be set by procsignal_sigusr1_handler */ +} + +/* + * WrapExecProcNodeWithExplain - + * Wrap ExecProcNode with ExecProcNodeWithExplain recursively + */ +static void +WrapExecProcNodeWithExplain(PlanState *ps) +{ + /* wrapping can be done only once */ + if (ps->ExecProcNodeOriginal != NULL) + return; + + ps->ExecProcNodeOriginal = ps->ExecProcNode; + ps->ExecProcNode = ExecProcNodeWithExplain; + + if (ps->lefttree != NULL) + WrapExecProcNodeWithExplain(ps->lefttree); + if (ps->righttree != NULL) + WrapExecProcNodeWithExplain(ps->righttree); +} + +/* + * UnWrapExecProcNodeWithExplain - + * Unwrap ExecProcNode with ExecProcNodeWithExplain recursively + */ +static void +UnWrapExecProcNodeWithExplain(PlanState *ps) +{ + Assert(ps->ExecProcNodeOriginal != NULL); + + ps->ExecProcNode = ps->ExecProcNodeOriginal; + ps->ExecProcNodeOriginal = NULL; + + if (ps->lefttree != NULL) + UnWrapExecProcNodeWithExplain(ps->lefttree); + if (ps->righttree != NULL) + UnWrapExecProcNodeWithExplain(ps->righttree); +} + +/* + * ExecProcNodeWithExplain - + * Wrap ExecProcNode with codes which logs currently running plan + */ +static TupleTableSlot * +ExecProcNodeWithExplain(PlanState *ps) +{ + ExplainState *es; + MemoryContext cxt; + MemoryContext old_cxt; + + check_stack_depth(); + + 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; + + ExplainAssembleLogOutput(es, ActiveQueryDesc, EXPLAIN_FORMAT_TEXT, 0, -1); + + ereport(LOG_SERVER_ONLY, + errmsg("query plan running on backend with PID %d is:\n%s", + MyProcPid, es->str->data), + errhidestmt(true), + errhidecontext(true)); + + MemoryContextSwitchTo(old_cxt); + MemoryContextDelete(cxt); + + UnWrapExecProcNodeWithExplain(ActiveQueryDesc->planstate); + + /* + * Since unwrapping has already done, call ExecProcNode() not + * ExecProcNodeOriginal(). + */ + return ps->ExecProcNode(ps); +} + +/* + * ProcessLogQueryPlanInterrupt + * Add wrapper which logs explain of the plan to ExecProcNodes + * + * Since running EXPLAIN codes at any arbitrary CHECK_FOR_INTERRUPTS() seems + * unsafe, this function just wraps every ExecProcNodes. + * In this way, EXPLAIN code is only executed at the timing of ExecProcNode, + * which is safe. + */ +void +ProcessLogQueryPlanInterrupt(void) +{ + LogQueryPlanPending = false; + + /* Cannot re-enter */ + if (ProcessLogQueryPlanInterruptActive) + return; + + ProcessLogQueryPlanInterruptActive = true; + + if (ActiveQueryDesc == NULL) + { + ereport(LOG_SERVER_ONLY, + errmsg("backend with PID %d is not running a query or a subtransaction is aborted", + MyProcPid), + errhidestmt(true), + errhidecontext(true)); + + ProcessLogQueryPlanInterruptActive = false; + return; + } + + WrapExecProcNodeWithExplain(ActiveQueryDesc->planstate); + ProcessLogQueryPlanInterruptActive = false; +} + +/* + * pg_log_query_plan + * 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) + { + /* Again, just a warning to allow loops */ + 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/executor/execMain.c b/src/backend/executor/execMain.c index 940499cc61..407dc3fe91 100644 --- a/src/backend/executor/execMain.c +++ b/src/backend/executor/execMain.c @@ -55,6 +55,7 @@ #include "tcop/utility.h" #include "utils/acl.h" #include "utils/backend_status.h" +#include "utils/injection_point.h" #include "utils/lsyscache.h" #include "utils/partcache.h" #include "utils/rls.h" @@ -70,6 +71,9 @@ ExecutorEnd_hook_type ExecutorEnd_hook = NULL; /* Hook for plugin to get control in ExecCheckPermissions() */ ExecutorCheckPerms_hook_type ExecutorCheckPerms_hook = NULL; +/* Currently executing query's QueryDesc */ +QueryDesc *ActiveQueryDesc = NULL; + /* decls for local routines only used within this module */ static void InitPlan(QueryDesc *queryDesc, int eflags); static void CheckValidRowMarkRel(Relation rel, RowMarkType markType); @@ -295,10 +299,25 @@ ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count, bool execute_once) { + /* + * Update ActiveQueryDesc here to enable retrieval of the currently + * running queryDesc for nested queries. + */ + QueryDesc *save_ActiveQueryDesc; + + save_ActiveQueryDesc = ActiveQueryDesc; + ActiveQueryDesc = queryDesc; + +#ifdef USE_INJECTION_POINTS + INJECTION_POINT("executor-run"); +#endif + if (ExecutorRun_hook) (*ExecutorRun_hook) (queryDesc, direction, count, execute_once); else standard_ExecutorRun(queryDesc, direction, count, execute_once); + + ActiveQueryDesc = save_ActiveQueryDesc; } void diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c index ca41b56952..4043c62538 100644 --- a/src/backend/storage/ipc/procsignal.c +++ b/src/backend/storage/ipc/procsignal.c @@ -20,6 +20,7 @@ #include "access/parallel.h" #include "port/pg_bitutils.h" #include "commands/async.h" +#include "commands/explain.h" #include "miscadmin.h" #include "pgstat.h" #include "replication/logicalworker.h" @@ -652,6 +653,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 6b7903314a..e7fe9a1343 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -37,6 +37,7 @@ #include "catalog/pg_type.h" #include "commands/async.h" #include "commands/event_trigger.h" +#include "commands/explain.h" #include "commands/prepare.h" #include "common/pg_prng.h" #include "jit/jit.h" @@ -3460,6 +3461,9 @@ ProcessInterrupts(void) if (LogMemoryContextPending) ProcessLogMemoryContextInterrupt(); + if (LogQueryPlanPending) + ProcessLogQueryPlanInterrupt(); + if (ParallelApplyMessagePending) HandleParallelApplyMessages(); } diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c index 5b536ac50d..3e5b71f4e2 100644 --- a/src/backend/utils/init/globals.c +++ b/src/backend/utils/init/globals.c @@ -38,6 +38,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/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index 291ed876fc..a7b2860061 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -8267,6 +8267,12 @@ prorettype => 'bool', proargtypes => 'int4', prosrc => 'pg_log_backend_memory_contexts' }, +# 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' }, + # non-persistent series generator { oid => '1066', descr => 'non-persistent series generator', proname => 'generate_series', prorows => '1000', diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h index cf195f1359..2d06bf297e 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -17,6 +17,8 @@ #include "lib/stringinfo.h" #include "parser/parse_node.h" +extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive; + typedef enum ExplainFormat { EXPLAIN_FORMAT_TEXT, @@ -61,6 +63,7 @@ typedef struct ExplainState bool hide_workers; /* set if we find an invisible Gather */ /* state related to the current plan node */ ExplainWorkersState *workers_state; /* needed if parallel plan */ + bool signaled; /* whether explain is called by signal */ } ExplainState; /* Hook for plugins to get control in ExplainOneQuery() */ @@ -100,6 +103,10 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, const BufferUsage *bufusage, const MemoryContextCounters *mem_counters); +extern void ExplainAssembleLogOutput(ExplainState *es, QueryDesc *queryDesc, + int logFormat, bool logTriggers, + int logParameterMaxLength); + extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc); extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc); @@ -132,4 +139,6 @@ extern void ExplainOpenGroup(const char *objtype, const char *labelname, extern void ExplainCloseGroup(const char *objtype, const char *labelname, bool labeled, ExplainState *es); +extern void HandleLogQueryPlanInterrupt(void); +extern void ProcessLogQueryPlanInterrupt(void); #endif /* EXPLAIN_H */ diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h index f900da6157..745c1fa812 100644 --- a/src/include/miscadmin.h +++ b/src/include/miscadmin.h @@ -96,6 +96,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/nodes/execnodes.h b/src/include/nodes/execnodes.h index 444a5f0fd5..ddec21ab5d 100644 --- a/src/include/nodes/execnodes.h +++ b/src/include/nodes/execnodes.h @@ -1050,6 +1050,9 @@ typedef struct PlanState ExecProcNodeMtd ExecProcNodeReal; /* actual function, if above is a * wrapper */ + ExecProcNodeMtd ExecProcNodeOriginal; /* temporary place when adding + * process for ExecProcNode */ + Instrumentation *instrument; /* Optional runtime stats for this node */ WorkerInstrumentation *worker_instrument; /* per-worker instrumentation */ diff --git a/src/include/storage/procsignal.h b/src/include/storage/procsignal.h index 7d290ea7d0..2e7e1e2d45 100644 --- a/src/include/storage/procsignal.h +++ b/src/include/storage/procsignal.h @@ -35,6 +35,7 @@ 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 */ /* Recovery conflict reasons */ diff --git a/src/include/tcop/pquery.h b/src/include/tcop/pquery.h index 073fb323bc..3dd7edf93c 100644 --- a/src/include/tcop/pquery.h +++ b/src/include/tcop/pquery.h @@ -21,7 +21,7 @@ struct PlannedStmt; /* avoid including plannodes.h here */ extern PGDLLIMPORT Portal ActivePortal; - +extern PGDLLIMPORT QueryDesc *ActiveQueryDesc; extern PortalStrategy ChoosePortalStrategy(List *stmts); diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h index 054dd2bf62..3c6bd1ea7c 100644 --- a/src/include/utils/elog.h +++ b/src/include/utils/elog.h @@ -167,6 +167,7 @@ struct Node; extern bool message_level_is_interesting(int elevel); +extern PGDLLIMPORT bool ProcessLogQueryPlanInterruptActive; extern bool errstart(int elevel, const char *domain); extern pg_attribute_cold bool errstart_cold(int elevel, const char *domain); extern void errfinish(const char *filename, int lineno, const char *funcname); diff --git a/src/test/modules/injection_points/injection_points.c b/src/test/modules/injection_points/injection_points.c index 7f52d758c5..9e846f04e7 100644 --- a/src/test/modules/injection_points/injection_points.c +++ b/src/test/modules/injection_points/injection_points.c @@ -17,6 +17,7 @@ #include "postgres.h" +#include "commands/explain.h" #include "fmgr.h" #include "storage/condition_variable.h" #include "storage/lwlock.h" @@ -54,6 +55,7 @@ static InjectionPointSharedState *inj_state = NULL; extern PGDLLEXPORT void injection_error(const char *name); extern PGDLLEXPORT void injection_notice(const char *name); extern PGDLLEXPORT void injection_wait(const char *name); +extern PGDLLEXPORT void injection_HandleLogQueryPlanInterrupt(const char *name); /* @@ -160,6 +162,13 @@ injection_wait(const char *name) SpinLockRelease(&inj_state->lock); } +void +injection_HandleLogQueryPlanInterrupt(const char *name) +{ + HandleLogQueryPlanInterrupt(); + elog(LOG, "triggered injection_HandleLogQueryPlanInterrupt for injection point %s", name); +} + /* * SQL function for creating an injection point. */ @@ -177,6 +186,8 @@ injection_points_attach(PG_FUNCTION_ARGS) function = "injection_notice"; else if (strcmp(action, "wait") == 0) function = "injection_wait"; + else if (strcmp(action, "logqueryplan") == 0) + function = "injection_HandleLogQueryPlanInterrupt"; else elog(ERROR, "incorrect action \"%s\" for injection point creation", action); diff --git a/src/test/regress/expected/misc_functions.out b/src/test/regress/expected/misc_functions.out index d5f61dfad9..c51f379b84 100644 --- a/src/test/regress/expected/misc_functions.out +++ b/src/test/regress/expected/misc_functions.out @@ -276,14 +276,15 @@ SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno'); ../jkl/mno (1 row) +-- Test logging functions -- --- pg_log_backend_memory_contexts() --- --- Memory contexts are logged and they are not returned to the function. +-- The outputs of these functions are logged and they are not returned to +-- the function. -- Furthermore, their contents can vary depending on the timing. However, -- we can at least verify that the code doesn't fail, and that the -- permissions are set properly. -- +-- pg_log_backend_memory_contexts() SELECT pg_log_backend_memory_contexts(pg_backend_pid()); pg_log_backend_memory_contexts -------------------------------- @@ -297,8 +298,8 @@ SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity t (1 row) -CREATE ROLE regress_log_memory; -SELECT has_function_privilege('regress_log_memory', +CREATE ROLE regress_log_function; +SELECT has_function_privilege('regress_log_function', 'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no has_function_privilege ------------------------ @@ -306,15 +307,15 @@ SELECT has_function_privilege('regress_log_memory', (1 row) GRANT EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer) - TO regress_log_memory; -SELECT has_function_privilege('regress_log_memory', + TO regress_log_function; +SELECT has_function_privilege('regress_log_function', 'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes has_function_privilege ------------------------ t (1 row) -SET ROLE regress_log_memory; +SET ROLE regress_log_function; SELECT pg_log_backend_memory_contexts(pg_backend_pid()); pg_log_backend_memory_contexts -------------------------------- @@ -323,8 +324,41 @@ SELECT pg_log_backend_memory_contexts(pg_backend_pid()); RESET ROLE; REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer) - FROM regress_log_memory; -DROP ROLE regress_log_memory; + FROM regress_log_function; +-- pg_log_query_plan() +SELECT pg_log_query_plan(pg_backend_pid()); + pg_log_query_plan +------------------- + t +(1 row) + +SELECT has_function_privilege('regress_log_function', + '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_function; +SELECT has_function_privilege('regress_log_function', + 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes + has_function_privilege +------------------------ + t +(1 row) + +SET ROLE regress_log_function; +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_function; +DROP ROLE regress_log_function; -- -- Test some built-in SRFs -- diff --git a/src/test/regress/sql/misc_functions.sql b/src/test/regress/sql/misc_functions.sql index 928b04db7f..8e603b7255 100644 --- a/src/test/regress/sql/misc_functions.sql +++ b/src/test/regress/sql/misc_functions.sql @@ -68,39 +68,60 @@ SELECT test_canonicalize_path('./abc/./def/.'); SELECT test_canonicalize_path('./abc/././def/.'); SELECT test_canonicalize_path('./abc/./def/.././ghi/../../../jkl/mno'); +-- Test logging functions -- --- pg_log_backend_memory_contexts() --- --- Memory contexts are logged and they are not returned to the function. +-- The outputs of these functions are logged and they are not returned to +-- the function. -- Furthermore, their contents can vary depending on the timing. However, -- we can at least verify that the code doesn't fail, and that the -- permissions are set properly. -- +-- pg_log_backend_memory_contexts() + SELECT pg_log_backend_memory_contexts(pg_backend_pid()); SELECT pg_log_backend_memory_contexts(pid) FROM pg_stat_activity WHERE backend_type = 'checkpointer'; -CREATE ROLE regress_log_memory; +CREATE ROLE regress_log_function; -SELECT has_function_privilege('regress_log_memory', +SELECT has_function_privilege('regress_log_function', 'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- no GRANT EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer) - TO regress_log_memory; + TO regress_log_function; -SELECT has_function_privilege('regress_log_memory', +SELECT has_function_privilege('regress_log_function', 'pg_log_backend_memory_contexts(integer)', 'EXECUTE'); -- yes -SET ROLE regress_log_memory; +SET ROLE regress_log_function; SELECT pg_log_backend_memory_contexts(pg_backend_pid()); RESET ROLE; REVOKE EXECUTE ON FUNCTION pg_log_backend_memory_contexts(integer) - FROM regress_log_memory; + FROM regress_log_function; + +-- pg_log_query_plan() +SELECT pg_log_query_plan(pg_backend_pid()); + +SELECT has_function_privilege('regress_log_function', + 'pg_log_query_plan(integer)', 'EXECUTE'); -- no + +GRANT EXECUTE ON FUNCTION pg_log_query_plan(integer) + TO regress_log_function; + +SELECT has_function_privilege('regress_log_function', + 'pg_log_query_plan(integer)', 'EXECUTE'); -- yes + +SET ROLE regress_log_function; +SELECT pg_log_query_plan(pg_backend_pid()); +RESET ROLE; + +REVOKE EXECUTE ON FUNCTION pg_log_query_plan(integer) + FROM regress_log_function; -DROP ROLE regress_log_memory; +DROP ROLE regress_log_function; -- -- Test some built-in SRFs base-commit: 0b84f5c419a300dc1b1a70cf63b9907208e52643 -- 2.39.2