v4-0001-Add-NESTED_STATEMENTS-option-to-EXPLAIN.patch
application/octet-stream
Filename: v4-0001-Add-NESTED_STATEMENTS-option-to-EXPLAIN.patch
Type: application/octet-stream
Part: 1
Patch
Same data as JSON:
GET /api/v1/attachments/:id/patch
the parsed metadata as JSON — format, series position, per-file stats; never the diff bytes.
API reference →
Format: format-patch
Series: patch v4-0001
Subject: Add NESTED_STATEMENTS option to EXPLAIN
| File | + | − |
|---|---|---|
| doc/src/sgml/ref/explain.sgml | 338 | 0 |
| src/backend/commands/explain.c | 577 | 34 |
| src/backend/commands/explain_state.c | 25 | 0 |
| src/backend/commands/trigger.c | 17 | 1 |
| src/include/commands/explain_state.h | 2 | 0 |
| src/include/commands/trigger.h | 2 | 0 |
From b95e3addb6a0deb3fd9474df7231d45f1d83a75e Mon Sep 17 00:00:00 2001
From: Mohamed Ali <moali.pg@gmail.com>
Date: Fri, 15 May 2026 15:10:31 -0700
Subject: [PATCH v4] Add NESTED_STATEMENTS option to EXPLAIN
Add a new EXPLAIN option, NESTED_STATEMENTS, that captures and displays
execution plans for SQL statements executed within called functions,
procedures, and triggers. This provides similar functionality to
auto_explain's log_nested_statements parameter but as a core EXPLAIN
option requiring no extension or GUC configuration.
Features:
- NESTED_STATEMENTS boolean option (requires ANALYZE)
- Installs executor hooks (Start/Run/Finish/End) to track nesting
- Captures plan text, query text, nesting level, and execution time
- Displays nested plans after the main query plan
- SHOW_NESTED integer option to limit displayed plans (0 = summary only)
- Nested Statements Summary with total count, max depth, and timing
- Per-statement execution time with percentage (level-1 statements only;
deeper levels show absolute time since their time is already included
in their level-1 parent's inclusive time)
- Total Nested Time sums only level-1 statement times to avoid
double-counting when multi-level nesting is present
- Trigger detection via GetMyTriggerDepth(): detects both BEFORE and
AFTER triggers, annotates with (trigger) in output
- Separate Total Trigger Time tracking (level-1 triggers only, shown
as % of nested time)
- Works directly on DML with triggers (no function wrapper needed)
- Reveals trigger activity inside functions (unreachable by built-in
trigger reporting which only covers the top-level statement)
- Inherits parent EXPLAIN options (VERBOSE, COSTS, BUFFERS, WAL, FORMAT)
- Structured output for JSON/XML/YAML formats
- Error-safe: PG_TRY/PG_FINALLY ensures hook cleanup on errors
- Reentrancy guard: nested EXPLAIN(NESTED_STATEMENTS) does not crash
- Dedicated memory context: no leaks, freed in PG_FINALLY
trigger.c changes:
- Add GetMyTriggerDepth() getter function for MyTriggerDepth
- Refactor pg_trigger_depth() SQL function to use the getter
Documentation updated with parameter descriptions, notes on trigger
detection, level-1 timing semantics, and examples in TEXT, SHOW_NESTED,
and JSON formats.
---
doc/src/sgml/ref/explain.sgml | 338 +++++++++++++++
src/backend/commands/explain.c | 611 +++++++++++++++++++++++++--
src/backend/commands/explain_state.c | 25 ++
src/backend/commands/trigger.c | 18 +-
src/include/commands/explain_state.h | 2 +
src/include/commands/trigger.h | 2 +
6 files changed, 961 insertions(+), 35 deletions(-)
diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml
index e95e19081e1..1482426fe65 100644
--- a/doc/src/sgml/ref/explain.sgml
+++ b/doc/src/sgml/ref/explain.sgml
@@ -47,6 +47,8 @@ EXPLAIN [ ( <replaceable class="parameter">option</replaceable> [, ...] ) ] <rep
SUMMARY [ <replaceable class="parameter">boolean</replaceable> ]
MEMORY [ <replaceable class="parameter">boolean</replaceable> ]
IO [ <replaceable class="parameter">boolean</replaceable> ]
+ NESTED_STATEMENTS [ <replaceable class="parameter">boolean</replaceable> ]
+ SHOW_NESTED <replaceable class="parameter">integer</replaceable>
FORMAT { TEXT | XML | JSON | YAML }
</synopsis>
</refsynopsisdiv>
@@ -310,6 +312,70 @@ ROLLBACK;
</listitem>
</varlistentry>
+ <varlistentry>
+ <term><literal>NESTED_STATEMENTS</literal></term>
+ <listitem>
+ <para>
+ 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.
+ </para>
+ <para>
+ 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 <literal>PERFORM</literal> or
+ <literal>SELECT ... INTO</literal> run at a deeper level than the
+ caller, while statements in a function called via expression assignment
+ (e.g., <literal>result := func()</literal>) run at the same level as
+ the caller. Statements fired by triggers (both
+ <literal>BEFORE</literal> and <literal>AFTER</literal>) are
+ automatically detected and annotated with
+ <literal>(trigger)</literal> in the output. Nested statements that
+ fire triggers also show trigger timing information in their plan.
+ When <literal>VERBOSE</literal> is enabled, each nested statement
+ includes its <literal>Query Identifier</literal> for correlation
+ with <structname>pg_stat_statements</structname>.
+ </para>
+ <para>
+ This option provides similar functionality to
+ <xref linkend="auto-explain"/>'s
+ <varname>auto_explain.log_nested_statements</varname> parameter, but
+ without requiring the extension to be loaded or any GUC configuration.
+ It also works directly on DML statements
+ (<command>INSERT</command>, <command>UPDATE</command>,
+ <command>DELETE</command>) that fire triggers, revealing the
+ execution plans of trigger-fired statements without needing to
+ wrap the query in a function.
+ A summary section is included after the nested plans showing
+ total statement count, execution time breakdown, and the slowest
+ statement (controlled by the <literal>SUMMARY</literal> option).
+ This parameter may only be used when <literal>ANALYZE</literal> is also
+ enabled. It defaults to <literal>FALSE</literal>.
+ </para>
+ </listitem>
+ </varlistentry>
+
+ <varlistentry>
+ <term><literal>SHOW_NESTED</literal></term>
+ <listitem>
+ <para>
+ Limit the number of nested statement plans displayed in the output.
+ When specified, only the first <replaceable>N</replaceable> nested
+ plans are shown, but all statements are still captured internally
+ for the summary statistics. Use <literal>SHOW_NESTED 0</literal>
+ to display only the summary without any individual plans.
+ This is useful for complex functions with many nested statements
+ where the full output would be too large.
+ This parameter may only be used when <literal>NESTED_STATEMENTS</literal>
+ is also enabled. When not specified, all nested plans are displayed.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry>
<term><literal>FORMAT</literal></term>
<listitem>
@@ -391,6 +457,55 @@ ROLLBACK;
execution, and on machines that have relatively slow operating
system calls for obtaining the time of day.
</para>
+
+ <para>
+ When <literal>NESTED_STATEMENTS</literal> is enabled, the options
+ <literal>VERBOSE</literal>, <literal>COSTS</literal>,
+ <literal>BUFFERS</literal>, <literal>WAL</literal>,
+ <literal>TIMING</literal>, and <literal>FORMAT</literal>
+ are inherited by the nested statement plans.
+ Each nested statement shows its execution time when
+ <literal>SUMMARY</literal> is enabled. Level-1 statements (those
+ directly inside the called function) also show a percentage of total
+ nested time. Deeper-level statements show only absolute time because
+ their time is already included in their level-1 parent's reported time.
+ Nested statements are numbered in completion order.
+ When using structured output formats (JSON, XML, YAML), each nested
+ plan is emitted as a structured object matching the main plan format.
+ </para>
+
+ <para>
+ A summary section controlled by <literal>SUMMARY</literal> shows:
+ total statement count, maximum nesting depth, total nested execution
+ time (as percentage of main execution time), total trigger time
+ (as percentage of nested time), and the slowest statement.
+ Total nested time sums only level-1 statement times to avoid
+ double-counting when deeper levels are present (since level-1
+ times already include their children's execution time).
+ Use <literal>SHOW_NESTED 0</literal> to display only the summary.
+ </para>
+
+ <para>
+ Statements fired by triggers (both <literal>BEFORE</literal> and
+ <literal>AFTER</literal>) are annotated with
+ <literal>(trigger)</literal> in the output header. Their time is
+ tracked separately as <literal>Total Trigger Time</literal> and
+ excluded from <literal>Total Nested Time</literal>. Nested
+ statements that fire triggers also show
+ <literal>Trigger</literal> lines (name, time, call count) in their
+ plan output, matching the main query's trigger reporting format.
+ </para>
+
+ <para>
+ When a function uses dynamic SQL via <literal>EXECUTE</literal>,
+ the <literal>Query Text</literal> field shows the actual executed
+ SQL string, not the PL/pgSQL source expression.
+ When <literal>VERBOSE</literal> is enabled and
+ <varname>compute_query_id</varname> is active, each nested statement
+ shows its <literal>Query Identifier</literal>, which can be used to
+ look up the statement in
+ <structname>pg_stat_statements</structname>.
+ </para>
</refsect1>
<refsect1>
@@ -575,6 +690,229 @@ EXPLAIN (GENERIC_PLAN)
GROUP BY foo;
</programlisting>
</para>
+
+ <para>
+ To display execution plans for nested statements within a function:
+
+<programlisting>
+EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT my_function();
+
+ QUERY PLAN
+-------------------------------------------------------------
+ Result (cost=0.00..0.26 rows=1 width=4) (actual time=1.234..1.235 rows=1.00 loops=1)
+ Planning Time: 0.050 ms
+ Execution Time: 1.300 ms
+
+ Nested Plans:
+
+ Nested Statement #1 (level 1):
+ Query Text: SELECT count(*) FROM products
+ Aggregate (cost=11.75..11.76 rows=1 width=8) (actual time=0.200..0.201 rows=1.00 loops=1)
+ -> Seq Scan on products (cost=0.00..11.00 rows=500 width=0) (actual time=0.010..0.150 rows=500.00 loops=1)
+ Execution Time: 0.201 ms (20.1%)
+
+ Nested Statement #2 (level 1):
+ Query Text: UPDATE products SET price = price * 1.10 WHERE category = 'Electronics'
+ Update on products (cost=0.00..12.50 rows=0 width=0) (actual time=0.800..0.800 rows=0.00 loops=1)
+ -> Seq Scan on products (cost=0.00..12.50 rows=50 width=10) (actual time=0.050..0.100 rows=50.00 loops=1)
+ Filter: (category = 'Electronics'::text)
+ Rows Removed by Filter: 450
+ Execution Time: 0.800 ms (79.9%)
+
+ Nested Statements Summary:
+ Total: 2 statements, max depth 1
+ Total Execution Time: 1.300 ms
+ Total Nested Time: 1.001 ms (77.0% of total time)
+ Slowest Statement: #2 (0.800 ms, 79.9%)
+</programlisting>
+
+ This shows the main query plan followed by the execution plans for
+ each SQL statement executed inside <function>my_function()</function>.
+ </para>
+
+ <para>
+ When triggers are involved, trigger-fired statements are annotated
+ and the parent statement shows trigger timing:
+
+<programlisting>
+EXPLAIN (ANALYZE, NESTED_STATEMENTS, COSTS OFF)
+UPDATE orders SET status = 'done' WHERE id = 1;
+
+ QUERY PLAN
+-------------------------------------------------------------
+ Update on orders (actual time=0.050..0.050 rows=0.00 loops=1)
+ -> Index Scan using orders_pkey on orders (...)
+ Trigger audit_trigger: time=0.522 calls=1
+ Execution Time: 0.600 ms
+
+ Nested Plans:
+
+ Nested Statement #1 (level 1, trigger):
+ Query Text: INSERT INTO audit_log VALUES (NEW.id, 'status changed')
+ Insert on audit_log (actual time=0.010..0.010 rows=0.00 loops=1)
+ -> Result (actual time=0.001..0.001 rows=1.00 loops=1)
+ Execution Time: 0.011 ms
+
+ Nested Statements Summary:
+ Total: 1 statements (0 direct, 1 trigger-fired), max depth 1
+ Total Execution Time: 0.600 ms
+ Total Trigger Time: 0.011 ms
+ Slowest Statement: #1 (0.011 ms)
+</programlisting>
+ </para>
+
+ <para>
+ Use <literal>SHOW_NESTED</literal> to limit the number of plans displayed
+ when a function executes many statements:
+
+<programlisting>
+EXPLAIN (ANALYZE, NESTED_STATEMENTS, SHOW_NESTED 1) SELECT my_function();
+
+ QUERY PLAN
+-------------------------------------------------------------
+ Result (cost=0.00..0.26 rows=1 width=4) (actual time=1.234..1.235 rows=1.00 loops=1)
+ Planning Time: 0.050 ms
+ Execution Time: 1.300 ms
+
+ Nested Plans (showing 1 of 2):
+
+ Nested Statement #1 (level 1):
+ Query Text: SELECT count(*) FROM products
+ Aggregate (cost=11.75..11.76 rows=1 width=8) (actual time=0.200..0.201 rows=1.00 loops=1)
+ -> Seq Scan on products (cost=0.00..11.00 rows=500 width=0) (actual time=0.010..0.150 rows=500.00 loops=1)
+ Execution Time: 0.201 ms (20.1%)
+
+ Nested Statements Summary:
+ Total: 2 statements, max depth 1
+ Total Execution Time: 1.300 ms
+ Total Nested Time: 1.001 ms (77.0% of total time)
+ Slowest Statement: #2 (0.800 ms, 79.9%)
+</programlisting>
+
+ Only the first plan is shown, but the summary still reflects all
+ statements. Use <literal>SHOW_NESTED 0</literal> to display only
+ the summary without any individual plans.
+ </para>
+
+ <para>
+ 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:
+
+<programlisting>
+EXPLAIN (ANALYZE, NESTED_STATEMENTS, FORMAT JSON) SELECT my_function();
+
+ QUERY PLAN
+-------------------------------------------------------------
+[
+ {
+ "Plan": {
+ "Node Type": "Result",
+ "Startup Cost": 0.00,
+ "Total Cost": 0.26,
+ "Plan Rows": 1,
+ "Plan Width": 4,
+ "Actual Startup Time": 1.234,
+ "Actual Total Time": 1.235,
+ "Actual Rows": 1,
+ "Actual Loops": 1
+ },
+ "Planning Time": 0.050,
+ "Execution Time": 1.300
+ }
+]
+
+Nested Plans:
+
+Nested Statement #1 (level 1):
+Query Text: SELECT count(*) FROM products
+[
+ {
+ "Plan": {
+ "Node Type": "Aggregate",
+ "Startup Cost": 11.75,
+ "Total Cost": 11.76,
+ "Plan Rows": 1,
+ "Plan Width": 8,
+ "Actual Startup Time": 0.200,
+ "Actual Total Time": 0.201,
+ "Actual Rows": 1,
+ "Actual Loops": 1,
+ "Plans": [
+ {
+ "Node Type": "Seq Scan",
+ "Parent Relationship": "Outer",
+ "Relation Name": "products",
+ "Alias": "products",
+ "Startup Cost": 0.00,
+ "Total Cost": 11.00,
+ "Plan Rows": 500,
+ "Plan Width": 0,
+ "Actual Startup Time": 0.010,
+ "Actual Total Time": 0.150,
+ "Actual Rows": 500,
+ "Actual Loops": 1
+ }
+ ]
+ },
+ "Execution Time": 0.201
+ }
+]
+
+Nested Statement #2 (level 1):
+Query Text: UPDATE products SET price = price * 1.10 WHERE category = 'Electronics'
+[
+ {
+ "Plan": {
+ "Node Type": "ModifyTable",
+ "Operation": "Update",
+ "Relation Name": "products",
+ "Alias": "products",
+ "Startup Cost": 0.00,
+ "Total Cost": 12.50,
+ "Plan Rows": 0,
+ "Plan Width": 0,
+ "Actual Startup Time": 0.800,
+ "Actual Total Time": 0.800,
+ "Actual Rows": 0,
+ "Actual Loops": 1,
+ "Plans": [
+ {
+ "Node Type": "Seq Scan",
+ "Parent Relationship": "Outer",
+ "Relation Name": "products",
+ "Alias": "products",
+ "Startup Cost": 0.00,
+ "Total Cost": 12.50,
+ "Plan Rows": 50,
+ "Plan Width": 10,
+ "Actual Startup Time": 0.050,
+ "Actual Total Time": 0.100,
+ "Actual Rows": 50,
+ "Actual Loops": 1,
+ "Filter": "(category = 'Electronics'::text)",
+ "Rows Removed by Filter": 450
+ }
+ ]
+ },
+ "Execution Time": 0.800
+ }
+]
+
+Nested Statements Summary:
+ Total: 2 statements, max depth 1
+ Total Execution Time: 1.300 ms
+ Total Nested Time: 1.001 ms (77.0% of total time)
+ Slowest Statement: #2 (0.800 ms, 79.9%)
+</programlisting>
+
+ Each nested plan is a valid JSON document that can be parsed independently.
+ The metadata headers (statement number, nesting level, query text) and the
+ summary appear as plain text between the JSON blocks. The
+ <literal>Execution Time</literal> field is included inside each nested
+ plan's JSON structure when <literal>SUMMARY</literal> is enabled.
+ Percentages are shown only in the text-format summary, not inside the
+ structured plan objects.
+ </para>
</refsect1>
<refsect1>
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 112c17b0d64..222583000f0 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -23,6 +23,8 @@
#include "commands/explain_format.h"
#include "commands/explain_state.h"
#include "commands/prepare.h"
+#include "commands/trigger.h"
+#include "executor/executor.h"
#include "foreign/fdwapi.h"
#include "jit/jit.h"
#include "libpq/pqformat.h"
@@ -58,6 +60,49 @@ 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 */
+ bool is_trigger; /* true if fired by a trigger */
+ 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 int nested_total_count = 0;
+static int nested_max_depth = 0;
+static double nested_total_time = 0.0;
+static double nested_slowest_time = 0.0;
+static int nested_slowest_num = 0;
+static double nested_main_exec_time = 0.0;
+static double nested_trigger_time = 0.0;
+static int nested_trigger_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 +251,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)
+ PG_TRY();
{
- /*
- * 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;
+ /* 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;
+
+ /* 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);
+ /* 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();
}
/*
@@ -686,6 +756,10 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
ExplainPropertyFloat("Execution Time", "ms", 1000.0 * totaltime, 3,
es);
+ /* Store main execution time for nested statements percentage calculation */
+ if (es->nested_statements && nested_tracking_active)
+ nested_main_exec_time = 1000.0 * totaltime;
+
ExplainCloseGroup("Query", NULL, true, es);
}
@@ -5322,3 +5396,472 @@ 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_total_count = 0;
+ nested_max_depth = 0;
+ nested_total_time = 0.0;
+ nested_slowest_time = 0.0;
+ nested_slowest_num = 0;
+ nested_main_exec_time = 0.0;
+ nested_trigger_time = 0.0;
+ nested_trigger_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. Uses GetMyTriggerDepth() to detect whether the
+ * statement was fired by a trigger (both BEFORE and AFTER).
+ */
+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)
+ {
+ double stmt_time = -1.0;
+ bool is_trigger = (GetMyTriggerDepth() > 0);
+
+ nested_total_count++;
+ if (is_trigger)
+ nested_trigger_count++;
+
+ /* Track timing for summary (always, even if not displaying) */
+ if (queryDesc->query_instr)
+ {
+ stmt_time = INSTR_TIME_GET_MILLISEC(queryDesc->query_instr->total);
+ if (is_trigger && nested_exec_level == 1)
+ {
+ /*
+ * Only sum level-1 trigger statements into Total Trigger Time.
+ * A level-1 trigger's inclusive time already contains any
+ * cascading triggers at deeper levels.
+ */
+ nested_trigger_time += stmt_time;
+ }
+ else if (!is_trigger && nested_exec_level == 1)
+ {
+ /*
+ * Only sum level-1 statements into Total Nested Time.
+ * Level-1 statements already include deeper levels' time
+ * (inclusive timing), so summing all levels would
+ * double-count.
+ */
+ nested_total_time += stmt_time;
+ }
+ if (!is_trigger && nested_exec_level == 1 &&
+ stmt_time > nested_slowest_time)
+ {
+ nested_slowest_time = stmt_time;
+ nested_slowest_num = nested_total_count;
+ }
+ }
+
+ /* Track max depth */
+ if (nested_exec_level > nested_max_depth)
+ nested_max_depth = nested_exec_level;
+
+ /*
+ * Only capture plan text if under the display limit.
+ * show_nested < 0 means show all (no limit).
+ */
+ if (nested_parent_es->show_nested < 0 ||
+ nested_stmt_count < nested_parent_es->show_nested)
+ {
+ 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.
+ */
+ 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);
+
+ /* Print trigger info for this nested statement (matches
+ * what top-level EXPLAIN does for the main query) */
+ if (nes->analyze)
+ ExplainPrintTriggers(nes, queryDesc);
+
+ /* Add Execution Time inside structured output for non-TEXT */
+ if (nes->format != EXPLAIN_FORMAT_TEXT &&
+ queryDesc->query_instr &&
+ nested_parent_es->summary)
+ ExplainPropertyFloat("Execution Time", "ms", stmt_time, 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_total_count;
+ plan_info->nesting_level = nested_exec_level;
+ plan_info->query_text = queryDesc->sourceText ?
+ pstrdup(queryDesc->sourceText) : pstrdup("<unknown>");
+ plan_info->plan_text = pstrdup(nes->str->data);
+ plan_info->exec_time_ms = stmt_time;
+ plan_info->is_trigger = is_trigger;
+ 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;
+
+ if (nested_plans_head == NULL && nested_total_count == 0)
+ return;
+
+ if (es->format == EXPLAIN_FORMAT_TEXT)
+ {
+ appendStringInfoChar(es->str, '\n');
+ if (nested_total_count > nested_stmt_count)
+ appendStringInfo(es->str, "Nested Plans (showing %d of %d):\n",
+ nested_stmt_count, nested_total_count);
+ else
+ appendStringInfoString(es->str, "Nested Plans:\n");
+
+ for (info = nested_plans_head; info != NULL; info = info->next)
+ {
+ appendStringInfoChar(es->str, '\n');
+ if (info->is_trigger)
+ appendStringInfo(es->str, " Nested Statement #%d (level %d, trigger):\n",
+ info->statement_num, info->nesting_level);
+ else
+ 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)
+ {
+ if (info->is_trigger)
+ {
+ /* Trigger time is included in parent's time;
+ * header already shows "(trigger)" annotation */
+ appendStringInfo(es->str, " Execution Time: %.3f ms\n",
+ info->exec_time_ms);
+ }
+ else if (info->nesting_level == 1 && nested_total_time > 0)
+ {
+ /*
+ * Only level-1 statements show percentage, since
+ * Total Nested Time sums only level-1 times.
+ * Deeper statements show absolute time only (their
+ * time is already included in their level-1 parent).
+ */
+ double pct = (info->exec_time_ms / nested_total_time) * 100.0;
+ appendStringInfo(es->str, " Execution Time: %.3f ms (%.1f%%)\n",
+ info->exec_time_ms, pct);
+ }
+ else
+ 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 */
+ if (nested_total_count > nested_stmt_count)
+ appendStringInfo(es->str, "\n\nNested Plans (showing %d of %d):\n",
+ nested_stmt_count, nested_total_count);
+ else
+ appendStringInfoString(es->str, "\n\nNested Plans:\n");
+
+ for (info = nested_plans_head; info != NULL; info = info->next)
+ {
+ appendStringInfoChar(es->str, '\n');
+ if (info->is_trigger)
+ appendStringInfo(es->str, "Nested Statement #%d (level %d, trigger):\n",
+ info->statement_num, info->nesting_level);
+ else
+ 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');
+ }
+ }
+
+ /* Print summary if enabled */
+ if (es->summary && nested_total_count > 0)
+ {
+ int direct_count = nested_total_count - nested_trigger_count;
+
+ appendStringInfoChar(es->str, '\n');
+ appendStringInfoString(es->str, "Nested Statements Summary:\n");
+
+ if (nested_trigger_count > 0)
+ appendStringInfo(es->str, " Total: %d statements (%d direct, %d trigger-fired), max depth %d\n",
+ nested_total_count, direct_count,
+ nested_trigger_count, nested_max_depth);
+ else
+ appendStringInfo(es->str, " Total: %d statements, max depth %d\n",
+ nested_total_count, nested_max_depth);
+
+ if (nested_main_exec_time > 0)
+ appendStringInfo(es->str, " Total Execution Time: %.3f ms\n",
+ nested_main_exec_time);
+
+ if (nested_total_time > 0)
+ {
+ if (nested_main_exec_time > 0)
+ {
+ double pct = (nested_total_time / nested_main_exec_time) * 100.0;
+ appendStringInfo(es->str, " Total Nested Time: %.3f ms (%.1f%% of total time)\n",
+ nested_total_time, pct);
+ }
+ else
+ appendStringInfo(es->str, " Total Nested Time: %.3f ms\n",
+ nested_total_time);
+ }
+
+ if (nested_trigger_time > 0)
+ {
+ if (nested_total_time > 0)
+ {
+ double pct = (nested_trigger_time / nested_total_time) * 100.0;
+ appendStringInfo(es->str, " Total Trigger Time: %.3f ms (%.1f%% of nested time)\n",
+ nested_trigger_time, pct);
+ }
+ else
+ appendStringInfo(es->str, " Total Trigger Time: %.3f ms\n",
+ nested_trigger_time);
+ }
+
+ if (nested_slowest_num > 0)
+ {
+ if (nested_total_time > 0)
+ {
+ double pct = (nested_slowest_time / nested_total_time) * 100.0;
+ appendStringInfo(es->str, " Slowest Statement: #%d (%.3f ms, %.1f%%)\n",
+ nested_slowest_num, nested_slowest_time, pct);
+ }
+ else
+ appendStringInfo(es->str, " Slowest Statement: #%d (%.3f ms)\n",
+ nested_slowest_num, nested_slowest_time);
+ }
+ }
+
+ /* 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..73bce1b350c 100644
--- a/src/backend/commands/explain_state.c
+++ b/src/backend/commands/explain_state.c
@@ -67,6 +67,7 @@ NewExplainState(void)
/* Set default options (most fields can be left as zeroes). */
es->costs = true;
+ es->show_nested = -1; /* show all nested plans by default */
/* Prepare output buffer. */
es->str = makeStringInfo();
@@ -164,6 +165,17 @@ 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 (strcmp(opt->defname, "show_nested") == 0)
+ {
+ es->show_nested = defGetInt32(opt);
+ if (es->show_nested < 0)
+ ereport(ERROR,
+ (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+ errmsg("EXPLAIN option %s must be a non-negative integer",
+ "SHOW_NESTED")));
+ }
else if (!ApplyExtensionExplainOption(es, opt, pstate))
ereport(ERROR,
(errcode(ERRCODE_SYNTAX_ERROR),
@@ -202,6 +214,19 @@ 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 SHOW_NESTED is used with NESTED_STATEMENTS */
+ if (es->show_nested >= 0 && !es->nested_statements)
+ ereport(ERROR,
+ (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+ errmsg("EXPLAIN option %s requires %s",
+ "SHOW_NESTED", "NESTED_STATEMENTS")));
+
/* check that GENERIC_PLAN is not used with EXPLAIN ANALYZE */
if (es->generic && es->analyze)
ereport(ERROR,
diff --git a/src/backend/commands/trigger.c b/src/backend/commands/trigger.c
index b87b4b40d07..097ddf800b0 100644
--- a/src/backend/commands/trigger.c
+++ b/src/backend/commands/trigger.c
@@ -6783,10 +6783,26 @@ assign_session_replication_role(int newval, void *extra)
/*
* SQL function pg_trigger_depth()
*/
+/*
+ * GetMyTriggerDepth - return current trigger nesting depth.
+ *
+ * This is a C-callable accessor for MyTriggerDepth, allowing other
+ * subsystems (e.g., EXPLAIN NESTED_STATEMENTS) to detect whether
+ * execution is currently inside a trigger function.
+ */
+int
+GetMyTriggerDepth(void)
+{
+ return MyTriggerDepth;
+}
+
+/*
+ * SQL-callable function to report trigger nesting depth.
+ */
Datum
pg_trigger_depth(PG_FUNCTION_ARGS)
{
- PG_RETURN_INT32(MyTriggerDepth);
+ PG_RETURN_INT32(GetMyTriggerDepth());
}
/*
diff --git a/src/include/commands/explain_state.h b/src/include/commands/explain_state.h
index 97bc7ed49f6..01fef3068b6 100644
--- a/src/include/commands/explain_state.h
+++ b/src/include/commands/explain_state.h
@@ -57,6 +57,8 @@ 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 */
+ int show_nested; /* how many nested plans to display (-1=all) */
ExplainSerializeOption serialize; /* serialize the query's output? */
ExplainFormat format; /* output format */
/* state for output formatting --- not reset for each new plan tree */
diff --git a/src/include/commands/trigger.h b/src/include/commands/trigger.h
index 1d9869973c0..83c97141876 100644
--- a/src/include/commands/trigger.h
+++ b/src/include/commands/trigger.h
@@ -310,4 +310,6 @@ extern void RegisterAfterTriggerBatchCallback(AfterTriggerBatchCallback callback
void *arg);
extern bool AfterTriggerIsActive(void);
+extern int GetMyTriggerDepth(void);
+
#endif /* TRIGGER_H */
--
2.50.1 (Apple Git-155)