From 6c3e246ba6c10a41687739e7aa5fba0deb48005d Mon Sep 17 00:00:00 2001 From: Mohamed Ali Date: Fri, 15 May 2026 15:10:31 -0700 Subject: [PATCH v1] Add NESTED_STATEMENTS option to EXPLAIN Add NESTED_STATEMENTS as a native EXPLAIN option, allowing users to view execution plans for queries executed within PL/pgSQL functions and procedures without requiring auto_explain or any extension. Usage: EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT my_function(); The feature works by temporarily installing executor hooks during EXPLAIN execution to track query nesting depth and capture plans for nested statements. Each nested statement is displayed with its sequential number, nesting level, query text, and complete execution plan including actual times and buffer usage. Key implementation details: - Adds nested_statements field to ExplainState structure - Parses the option in ParseExplainOptionList() - Validates that ANALYZE is also specified (required for execution) - Installs ExecutorStart/Run/Finish/End hooks during EXPLAIN - Collects nested query plans in a linked list - Displays nested plans after the main query plan - Supports both TEXT and structured output formats (JSON, XML, YAML) - Properly tracks nesting through ExecutorFinish for triggers - Cleans up hooks after EXPLAIN completes Author: Mohamed Ali --- doc/src/sgml/ref/explain.sgml | 80 +++++++ src/backend/commands/explain.c | 320 +++++++++++++++++++++++++++ src/backend/commands/explain_state.c | 8 + src/include/commands/explain_state.h | 1 + 4 files changed, 409 insertions(+) diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml index e95e19081e1..555f7af6520 100644 --- a/doc/src/sgml/ref/explain.sgml +++ b/doc/src/sgml/ref/explain.sgml @@ -47,6 +47,7 @@ EXPLAIN [ ( option [, ...] ) ] boolean ] MEMORY [ boolean ] IO [ boolean ] + NESTED_STATEMENTS [ boolean ] FORMAT { TEXT | XML | JSON | YAML } @@ -310,6 +311,39 @@ ROLLBACK; + + NESTED_STATEMENTS + + + Include execution plans for statements executed within called functions + and procedures. When a query invokes PL/pgSQL functions (or other + procedural language functions), those functions may internally execute + additional SQL statements. This option captures the execution plans + for all such nested statements and displays them after the main query + plan. + + + Each nested statement is shown with a sequential number, its nesting + level, the query text, and the complete execution plan. The nesting + level reflects the executor call stack depth: statements in a function + called via PERFORM or + SELECT ... INTO run at a deeper level than the + caller, while statements in a function called via expression assignment + (e.g., result := func()) run at the same level as + the caller. Statements fired by triggers appear at a deeper level + than the triggering statement. + + + This option provides similar functionality to + 's + auto_explain.log_nested_statements parameter, but + without requiring the extension to be loaded or any GUC configuration. + This parameter may only be used when ANALYZE is also + enabled. It defaults to FALSE. + + + + FORMAT @@ -391,6 +425,16 @@ ROLLBACK; execution, and on machines that have relatively slow operating system calls for obtaining the time of day. + + + When NESTED_STATEMENTS is enabled, the options + VERBOSE, COSTS, + BUFFERS, WAL, and + TIMING are inherited by the nested statement plans. + Nested statements are numbered in the order they complete execution; + for statements fired by triggers, this means the trigger's statement + appears before the statement that fired it. + @@ -575,6 +619,42 @@ EXPLAIN (GENERIC_PLAN) GROUP BY foo; + + + To display execution plans for nested statements within a function: + + +EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT my_function(); + + QUERY PLAN +------------------------------------------------------------- + Result (actual time=1.234..1.235 rows=1.00 loops=1) + Buffers: shared hit=50 + Planning Time: 0.050 ms + Execution Time: 2.500 ms + + Nested Plans: + + Nested Statement #1 (level 1): + Query Text: SELECT COUNT(*) FROM products + Aggregate (actual time=0.015..0.016 rows=1.00 loops=1) + Buffers: shared hit=1 + -> Seq Scan on products (actual time=0.010..0.011 rows=5.00 loops=1) + Buffers: shared hit=1 + + Nested Statement #2 (level 1): + Query Text: UPDATE products SET price = price * 1.10 WHERE category = 'Electronics' + Update on products (actual time=0.050..0.050 rows=0.00 loops=1) + Buffers: shared hit=5 + -> Seq Scan on products (actual time=0.020..0.022 rows=3.00 loops=1) + Filter: (category = 'Electronics'::text) + Buffers: shared hit=1 + + + This shows the main query plan followed by the plans for each SQL + statement executed inside my_function(). The + nesting level indicates the executor call stack depth. + diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 112c17b0d64..6f09388c50c 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -23,6 +23,7 @@ #include "commands/explain_format.h" #include "commands/explain_state.h" #include "commands/prepare.h" +#include "executor/executor.h" #include "foreign/fdwapi.h" #include "jit/jit.h" #include "libpq/pqformat.h" @@ -58,6 +59,38 @@ explain_get_index_name_hook_type explain_get_index_name_hook = NULL; explain_per_plan_hook_type explain_per_plan_hook = NULL; explain_per_node_hook_type explain_per_node_hook = NULL; +/* Nested statements tracking for EXPLAIN (NESTED_STATEMENTS) */ +typedef struct NestedPlanInfo +{ + int statement_num; + int nesting_level; + char *query_text; + char *plan_text; + struct NestedPlanInfo *next; +} NestedPlanInfo; + +static int nested_exec_level = 0; +static bool nested_tracking_active = false; +static ExplainState *nested_parent_es = NULL; +static int nested_stmt_count = 0; +static NestedPlanInfo *nested_plans_head = NULL; +static NestedPlanInfo *nested_plans_tail = NULL; + +/* Saved executor hook values for nested statements */ +static ExecutorStart_hook_type prev_ExecutorStart_hook = NULL; +static ExecutorRun_hook_type prev_ExecutorRun_hook = NULL; +static ExecutorFinish_hook_type prev_ExecutorFinish_hook = NULL; +static ExecutorEnd_hook_type prev_ExecutorEnd_hook = NULL; + +static void nested_ExecutorStart(QueryDesc *queryDesc, int eflags); +static void nested_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, + uint64 count); +static void nested_ExecutorFinish(QueryDesc *queryDesc); +static void nested_ExecutorEnd(QueryDesc *queryDesc); +static void ExplainPrintNestedPlans(ExplainState *es); +static void ExplainInstallNestedHooks(ExplainState *es); +static void ExplainRemoveNestedHooks(void); + /* * Various places within need to convert bytes to kilobytes. Round these up * to the next whole kilobyte. @@ -206,6 +239,10 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt, */ rewritten = QueryRewrite(castNode(Query, stmt->query)); + /* Install nested statement hooks if requested */ + if (es->nested_statements) + ExplainInstallNestedHooks(es); + /* emit opening boilerplate */ ExplainBeginOutput(es); @@ -235,6 +272,13 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt, } } + /* Print nested statement plans if collected */ + if (es->nested_statements) + { + ExplainPrintNestedPlans(es); + ExplainRemoveNestedHooks(); + } + /* emit closing boilerplate */ ExplainEndOutput(es); Assert(es->indent == 0); @@ -5322,3 +5366,279 @@ ExplainFlushWorkersState(ExplainState *es) pfree(wstate->worker_state_save); pfree(wstate); } + +/* + * ExplainInstallNestedHooks - install executor hooks for nested statement + * tracking. + * + * This sets up hooks to intercept ExecutorStart, ExecutorRun, + * ExecutorFinish, and ExecutorEnd calls so we can track nesting depth + * and capture plans for nested statements. + */ +static void +ExplainInstallNestedHooks(ExplainState *es) +{ + nested_tracking_active = true; + nested_exec_level = 0; + nested_stmt_count = 0; + nested_plans_head = NULL; + nested_plans_tail = NULL; + nested_parent_es = es; + + /* Save and install hooks */ + prev_ExecutorStart_hook = ExecutorStart_hook; + ExecutorStart_hook = nested_ExecutorStart; + prev_ExecutorRun_hook = ExecutorRun_hook; + ExecutorRun_hook = nested_ExecutorRun; + prev_ExecutorFinish_hook = ExecutorFinish_hook; + ExecutorFinish_hook = nested_ExecutorFinish; + prev_ExecutorEnd_hook = ExecutorEnd_hook; + ExecutorEnd_hook = nested_ExecutorEnd; +} + +/* + * ExplainRemoveNestedHooks - restore previous executor hooks. + */ +static void +ExplainRemoveNestedHooks(void) +{ + ExecutorStart_hook = prev_ExecutorStart_hook; + ExecutorRun_hook = prev_ExecutorRun_hook; + ExecutorFinish_hook = prev_ExecutorFinish_hook; + ExecutorEnd_hook = prev_ExecutorEnd_hook; + + prev_ExecutorStart_hook = NULL; + prev_ExecutorRun_hook = NULL; + prev_ExecutorFinish_hook = NULL; + prev_ExecutorEnd_hook = NULL; + + nested_tracking_active = false; + nested_parent_es = NULL; +} + +/* + * nested_ExecutorStart - ExecutorStart hook for nested statement tracking. + * + * When we're inside a nested execution (nesting_level > 0), enable + * instrumentation so we can capture actual execution statistics. + */ +static void +nested_ExecutorStart(QueryDesc *queryDesc, int eflags) +{ + if (nested_tracking_active && nested_exec_level > 0 && + (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0) + { + /* Enable instrumentation for nested statements */ + if (nested_parent_es->timing) + queryDesc->instrument_options |= INSTRUMENT_TIMER; + else + queryDesc->instrument_options |= INSTRUMENT_ROWS; + if (nested_parent_es->buffers) + queryDesc->instrument_options |= INSTRUMENT_BUFFERS; + if (nested_parent_es->wal) + queryDesc->instrument_options |= INSTRUMENT_WAL; + } + + if (prev_ExecutorStart_hook) + prev_ExecutorStart_hook(queryDesc, eflags); + else + standard_ExecutorStart(queryDesc, eflags); +} + +/* + * nested_ExecutorRun - ExecutorRun hook for nested statement tracking. + * + * Track nesting depth so we know when we're inside a nested execution. + */ +static void +nested_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count) +{ + nested_exec_level++; + PG_TRY(); + { + if (prev_ExecutorRun_hook) + prev_ExecutorRun_hook(queryDesc, direction, count); + else + standard_ExecutorRun(queryDesc, direction, count); + } + PG_FINALLY(); + { + nested_exec_level--; + } + PG_END_TRY(); +} + +/* + * nested_ExecutorFinish - ExecutorFinish hook for nested statement tracking. + * + * Track nesting depth through ExecutorFinish as well, since some statements + * (e.g., those with AFTER triggers) do work here. + */ +static void +nested_ExecutorFinish(QueryDesc *queryDesc) +{ + nested_exec_level++; + PG_TRY(); + { + if (prev_ExecutorFinish_hook) + prev_ExecutorFinish_hook(queryDesc); + else + standard_ExecutorFinish(queryDesc); + } + PG_FINALLY(); + { + nested_exec_level--; + } + PG_END_TRY(); +} + +/* + * nested_ExecutorEnd - ExecutorEnd hook for nested statement tracking. + * + * When a nested statement finishes execution, capture its plan text + * for later display. + */ +static void +nested_ExecutorEnd(QueryDesc *queryDesc) +{ + if (nested_tracking_active && + nested_exec_level > 0 && + nested_parent_es != NULL && + queryDesc->plannedstmt != NULL && + queryDesc->instrument_options != 0) + { + MemoryContext oldcxt; + NestedPlanInfo *plan_info; + ExplainState *nes; + + nested_stmt_count++; + + /* + * Switch to TopMemoryContext so the captured plan text survives + * until we print it. + */ + oldcxt = MemoryContextSwitchTo(TopMemoryContext); + + /* Build an ExplainState to format this nested plan */ + nes = NewExplainState(); + nes->analyze = true; + nes->verbose = nested_parent_es->verbose; + nes->costs = nested_parent_es->costs; + nes->buffers = nested_parent_es->buffers; + nes->wal = nested_parent_es->wal; + nes->timing = nested_parent_es->timing; + nes->summary = false; + nes->format = EXPLAIN_FORMAT_TEXT; + + ExplainBeginOutput(nes); + ExplainPrintPlan(nes, queryDesc); + ExplainEndOutput(nes); + + /* Remove trailing newline if present */ + if (nes->str->len > 0 && nes->str->data[nes->str->len - 1] == '\n') + nes->str->data[--nes->str->len] = '\0'; + + /* Allocate and fill the plan info node */ + plan_info = (NestedPlanInfo *) palloc(sizeof(NestedPlanInfo)); + plan_info->statement_num = nested_stmt_count; + plan_info->nesting_level = nested_exec_level; + plan_info->query_text = queryDesc->sourceText ? + pstrdup(queryDesc->sourceText) : pstrdup(""); + plan_info->plan_text = pstrdup(nes->str->data); + plan_info->next = NULL; + + /* Append to the linked list */ + if (nested_plans_tail == NULL) + { + nested_plans_head = plan_info; + nested_plans_tail = plan_info; + } + else + { + nested_plans_tail->next = plan_info; + nested_plans_tail = plan_info; + } + + MemoryContextSwitchTo(oldcxt); + } + + if (prev_ExecutorEnd_hook) + prev_ExecutorEnd_hook(queryDesc); + else + standard_ExecutorEnd(queryDesc); +} + +/* + * ExplainPrintNestedPlans - print collected nested statement plans. + * + * This is called after the main query plan has been printed, to append + * the nested statement plans to the EXPLAIN output. + */ +static void +ExplainPrintNestedPlans(ExplainState *es) +{ + NestedPlanInfo *info; + NestedPlanInfo *next; + + if (nested_plans_head == NULL) + return; + + if (es->format == EXPLAIN_FORMAT_TEXT) + { + appendStringInfoChar(es->str, '\n'); + appendStringInfoString(es->str, "Nested Plans:\n"); + + for (info = nested_plans_head; info != NULL; info = info->next) + { + appendStringInfoChar(es->str, '\n'); + appendStringInfo(es->str, " Nested Statement #%d (level %d):\n", + info->statement_num, info->nesting_level); + appendStringInfo(es->str, " Query Text: %s\n", info->query_text); + + /* Indent the plan text */ + { + char *line; + char *plan_copy = pstrdup(info->plan_text); + char *saveptr = NULL; + + for (line = strtok_r(plan_copy, "\n", &saveptr); + line != NULL; + line = strtok_r(NULL, "\n", &saveptr)) + { + appendStringInfo(es->str, " %s\n", line); + } + pfree(plan_copy); + } + } + } + else + { + /* For structured formats (JSON, XML, YAML) */ + ExplainOpenGroup("Nested Plans", "Nested Plans", false, es); + + for (info = nested_plans_head; info != NULL; info = info->next) + { + ExplainOpenGroup("Nested Statement", NULL, true, es); + ExplainPropertyInteger("Statement Number", NULL, + info->statement_num, es); + ExplainPropertyInteger("Nesting Level", NULL, + info->nesting_level, es); + ExplainPropertyText("Query Text", info->query_text, es); + ExplainPropertyText("Plan", info->plan_text, es); + ExplainCloseGroup("Nested Statement", NULL, true, es); + } + + ExplainCloseGroup("Nested Plans", "Nested Plans", false, es); + } + + /* Free the collected plans */ + for (info = nested_plans_head; info != NULL; info = next) + { + next = info->next; + pfree(info->query_text); + pfree(info->plan_text); + pfree(info); + } + nested_plans_head = NULL; + nested_plans_tail = NULL; +} diff --git a/src/backend/commands/explain_state.c b/src/backend/commands/explain_state.c index a0ee0a664be..0f6bbe9c6cf 100644 --- a/src/backend/commands/explain_state.c +++ b/src/backend/commands/explain_state.c @@ -164,6 +164,8 @@ ParseExplainOptionList(ExplainState *es, List *options, ParseState *pstate) } else if (strcmp(opt->defname, "io") == 0) es->io = defGetBoolean(opt); + else if (strcmp(opt->defname, "nested_statements") == 0) + es->nested_statements = defGetBoolean(opt); else if (!ApplyExtensionExplainOption(es, opt, pstate)) ereport(ERROR, (errcode(ERRCODE_SYNTAX_ERROR), @@ -202,6 +204,12 @@ ParseExplainOptionList(ExplainState *es, List *options, ParseState *pstate) (errcode(ERRCODE_INVALID_PARAMETER_VALUE), errmsg("EXPLAIN option %s requires ANALYZE", "SERIALIZE"))); + /* check that NESTED_STATEMENTS is used with EXPLAIN ANALYZE */ + if (es->nested_statements && !es->analyze) + ereport(ERROR, + (errcode(ERRCODE_INVALID_PARAMETER_VALUE), + errmsg("EXPLAIN option %s requires ANALYZE", "NESTED_STATEMENTS"))); + /* check that GENERIC_PLAN is not used with EXPLAIN ANALYZE */ if (es->generic && es->analyze) ereport(ERROR, diff --git a/src/include/commands/explain_state.h b/src/include/commands/explain_state.h index 97bc7ed49f6..c02f4dda266 100644 --- a/src/include/commands/explain_state.h +++ b/src/include/commands/explain_state.h @@ -57,6 +57,7 @@ typedef struct ExplainState bool settings; /* print modified settings */ bool io; /* print info about IO (prefetch, ...) */ bool generic; /* generate a generic plan */ + bool nested_statements; /* print nested statement plans */ ExplainSerializeOption serialize; /* serialize the query's output? */ ExplainFormat format; /* output format */ /* state for output formatting --- not reset for each new plan tree */ -- 2.50.1 (Apple Git-155)