From 29714f041b4270364376a69e17b6cbe99dd79e34 Mon Sep 17 00:00:00 2001 From: Mohamed Ali Date: Fri, 15 May 2026 15:10:31 -0700 Subject: [PATCH v3] 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(); Features: - Displays execution plans for all nested SQL statements - Shows nesting level (executor call stack depth) for each statement - Shows Execution Time per nested statement (controlled by SUMMARY) - Supports all output formats (TEXT, JSON, XML, YAML) with proper structured output for each format - Requires ANALYZE (validated with clear error message) - Works with BEGIN/ROLLBACK for safe analysis of DML functions Implementation: - Adds nested_statements field to ExplainState structure - Temporarily installs ExecutorStart/Run/Finish/End hooks during EXPLAIN - Uses dedicated memory context for captured plans (no leaks) - PG_TRY/PG_FINALLY ensures cleanup on error paths - Reentrancy guard prevents crashes with nested EXPLAIN calls - Hooks are properly chained (saves/restores previous hooks) Author: Mohamed Ali --- doc/src/sgml/ref/explain.sgml | 141 +++++++++ src/backend/commands/explain.c | 442 ++++++++++++++++++++++++--- src/backend/commands/explain_state.c | 8 + src/include/commands/explain_state.h | 1 + 4 files changed, 558 insertions(+), 34 deletions(-) diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml index e95e19081e1..3b817f71ba8 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, the complete execution plan, and its execution + time. 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,23 @@ 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, + TIMING, and FORMAT + are inherited by the nested statement plans. + Each nested statement also shows its total execution time when + SUMMARY is enabled (the default with + ANALYZE). + When using structured output formats (JSON, XML, YAML), each nested + statement's plan is emitted as a proper structured object with typed + fields, matching the format of the main query plan. + 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 +626,96 @@ 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 + Execution Time: 0.016 ms + + 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 + Execution Time: 0.050 ms + + + 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. + + + + With JSON format, the main plan is emitted as a complete JSON document, + followed by each nested statement's plan as a separate JSON document: + + +EXPLAIN (ANALYZE, NESTED_STATEMENTS, FORMAT JSON) SELECT my_function(); + + QUERY PLAN +------------------------------------------------------------- +[ + { + "Plan": { + "Node Type": "Result", + "Actual Rows": 1.00, + "Actual Loops": 1, + ... + }, + "Planning Time": 0.050, + "Execution Time": 2.500 + } +] + +Nested Plans: + +Nested Statement #1 (level 1): +Query Text: SELECT COUNT(*) FROM products +[ + { + "Plan": { + "Node Type": "Aggregate", + "Actual Rows": 1.00, + "Actual Loops": 1, + "Plans": [ + { + "Node Type": "Seq Scan", + "Relation Name": "products", + "Actual Rows": 5.00, + "Actual Loops": 1, + "Filter": "(category = 'Electronics'::text)" + } + ] + }, + "Execution Time": 0.016 + } +] + + + Each nested plan is a valid JSON document that can be parsed independently. + The metadata headers (statement number, nesting level, query text) appear + as plain text between the JSON blocks. + diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 112c17b0d64..41ee27c9a32 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,40 @@ 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; + double exec_time_ms; /* execution time in ms, -1 if unavailable */ + 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; +static MemoryContext nested_memcxt = 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,49 +241,74 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt, */ rewritten = QueryRewrite(castNode(Query, stmt->query)); - /* emit opening boilerplate */ - ExplainBeginOutput(es); + /* Install nested statement hooks if requested */ + if (es->nested_statements) + ExplainInstallNestedHooks(es); - if (rewritten == NIL) - { - /* - * In the case of an INSTEAD NOTHING, tell at least that. But in - * non-text format, the output is delimited, so this isn't necessary. - */ - if (es->format == EXPLAIN_FORMAT_TEXT) - appendStringInfoString(es->str, "Query rewrites to nothing\n"); - } - else + PG_TRY(); { - ListCell *l; + /* emit opening boilerplate */ + ExplainBeginOutput(es); - /* Explain every plan */ - foreach(l, rewritten) + if (rewritten == NIL) { - ExplainOneQuery(lfirst_node(Query, l), - CURSOR_OPT_PARALLEL_OK, NULL, es, - pstate, params); + /* + * In the case of an INSTEAD NOTHING, tell at least that. But in + * non-text format, the output is delimited, so this isn't necessary. + */ + if (es->format == EXPLAIN_FORMAT_TEXT) + appendStringInfoString(es->str, "Query rewrites to nothing\n"); + } + else + { + ListCell *l; - /* Separate plans with an appropriate separator */ - if (lnext(rewritten, l) != NULL) - ExplainSeparatePlans(es); + /* Explain every plan */ + foreach(l, rewritten) + { + ExplainOneQuery(lfirst_node(Query, l), + CURSOR_OPT_PARALLEL_OK, NULL, es, + pstate, params); + + /* Separate plans with an appropriate separator */ + if (lnext(rewritten, l) != NULL) + ExplainSeparatePlans(es); + } } - } - /* emit closing boilerplate */ - ExplainEndOutput(es); - Assert(es->indent == 0); + /* emit closing boilerplate */ + ExplainEndOutput(es); + Assert(es->indent == 0); - /* output tuples */ - tstate = begin_tup_output_tupdesc(dest, ExplainResultDesc(stmt), - &TTSOpsVirtual); - if (es->format == EXPLAIN_FORMAT_TEXT) - do_text_output_multiline(tstate, es->str->data); - else - do_text_output_oneline(tstate, es->str->data); - end_tup_output(tstate); + /* Print nested statement plans after main plan is complete */ + if (es->nested_statements) + ExplainPrintNestedPlans(es); + + /* output tuples */ + tstate = begin_tup_output_tupdesc(dest, ExplainResultDesc(stmt), + &TTSOpsVirtual); + if (es->format == EXPLAIN_FORMAT_TEXT) + do_text_output_multiline(tstate, es->str->data); + else + do_text_output_oneline(tstate, es->str->data); + end_tup_output(tstate); - pfree(es->str->data); + pfree(es->str->data); + } + PG_FINALLY(); + { + /* Always clean up nested statement hooks and memory */ + if (es->nested_statements) + { + ExplainRemoveNestedHooks(); + if (nested_memcxt) + { + MemoryContextDelete(nested_memcxt); + nested_memcxt = NULL; + } + } + } + PG_END_TRY(); } /* @@ -5322,3 +5382,317 @@ 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) +{ + /* + * Guard against reentrancy: if we're already tracking nested statements + * (e.g., a function executes EXPLAIN (NESTED_STATEMENTS) internally), + * skip hook installation to avoid corrupting the outer EXPLAIN's state. + */ + if (nested_tracking_active) + { + es->nested_statements = false; + return; + } + + nested_tracking_active = true; + nested_exec_level = 0; + nested_stmt_count = 0; + nested_plans_head = NULL; + nested_plans_tail = NULL; + nested_parent_es = es; + + /* + * Create a dedicated memory context for captured plan text. This ensures + * all allocations can be freed at once in the PG_FINALLY cleanup, whether + * the EXPLAIN succeeds or errors out. + */ + nested_memcxt = AllocSetContextCreate(CurrentMemoryContext, + "Nested EXPLAIN plans", + ALLOCSET_DEFAULT_SIZES); + + /* 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 per-node 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; + + /* Enable query-level instrumentation for execution time tracking */ + queryDesc->query_instr_options |= INSTRUMENT_TIMER; + } + + 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 the dedicated memory context so the captured plan text + * survives until we print it, and can be freed all at once in cleanup. + */ + oldcxt = MemoryContextSwitchTo(nested_memcxt); + + /* 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 = nested_parent_es->format; + + ExplainBeginOutput(nes); + ExplainOpenGroup("Query", NULL, true, nes); + ExplainPrintPlan(nes, queryDesc); + + /* Add Execution Time inside the structured output for non-TEXT formats */ + if (nes->format != EXPLAIN_FORMAT_TEXT && + queryDesc->query_instr && + nested_parent_es->summary) + ExplainPropertyFloat("Execution Time", "ms", + INSTR_TIME_GET_MILLISEC(queryDesc->query_instr->total), + 3, nes); + + ExplainCloseGroup("Query", NULL, true, nes); + 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; + + /* Capture execution time from query instrumentation if available */ + if (queryDesc->query_instr) + plan_info->exec_time_ms = + INSTR_TIME_GET_MILLISEC(queryDesc->query_instr->total); + else + plan_info->exec_time_ms = -1.0; + + /* 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; + + 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); + } + + /* Print execution time if available and summary is enabled */ + if (info->exec_time_ms >= 0 && es->summary) + appendStringInfo(es->str, " Execution Time: %.3f ms\n", + info->exec_time_ms); + } + } + else + { + /* For structured formats (JSON, XML, YAML) — append each nested + * plan as its own structured block after the main plan */ + appendStringInfoString(es->str, "\n\nNested 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); + /* Append the structured plan output (already in JSON/XML/YAML, + * with Execution Time included inside the structure) */ + appendStringInfoString(es->str, info->plan_text); + appendStringInfoChar(es->str, '\n'); + } + } + + /* No need to free individual items — MemoryContextDelete in PG_FINALLY + * will free everything in nested_memcxt at once. */ + 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)