[PATCH] Add NESTED_STATEMENTS option to EXPLAIN

Hello!

With some initial testing I was able to find 2 server crashes with the patch.

1: error during explain

CREATE OR REPLACE FUNCTION divz_plpgsql(x int) RETURNS int LANGUAGE plpgsql AS $$
DECLARE r int;
BEGIN
SELECT 1/x INTO r;
RETURN r;
END;
$$;
-- error during explain
EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT divz_plpgsql(0);
-- run another explain
EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT 1;
-- any next query crashes the server
SELECT 1;

2: any nested explain

CREATE FUNCTION f() RETURNS void LANGUAGE plpgsql AS $$
DECLARE r record;
BEGIN
FOR r IN EXECUTE 'EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT 1'
LOOP NULL; END LOOP;
END;
$$;

EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT f();

+		/*
+		 * Switch to TopMemoryContext so the captured plan text survives
+		 * until we print it.
+		 */
+		oldcxt = MemoryContextSwitchTo(TopMemoryContext);
...
+		ExplainBeginOutput(nes);
+		ExplainPrintPlan(nes, queryDesc);
+		ExplainEndOutput(nes);
...
+		plan_info->query_text = queryDesc->sourceText ?
+			pstrdup(queryDesc->sourceText) : pstrdup("<unknown>");

When is queryDesc freed? This seems like a memory leak.

Hi Zsolt,

Thanks for testing! I've identified the root causes and am working on
v2 with the fixes. Will share soon.

-- Mohamed Ali

Show quoted text

On Sat, May 16, 2026 at 4:15 AM Zsolt Parragi <zsolt.parragi@percona.com> wrote:

Hello!

With some initial testing I was able to find 2 server crashes with the patch.

1: error during explain

CREATE OR REPLACE FUNCTION divz_plpgsql(x int) RETURNS int LANGUAGE
plpgsql AS $$
DECLARE r int;
BEGIN
SELECT 1/x INTO r;
RETURN r;
END;
$$;
-- error during explain
EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT divz_plpgsql(0);
-- run another explain
EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT 1;
-- any next query crashes the server
SELECT 1;

2: any nested explain

CREATE FUNCTION f() RETURNS void LANGUAGE plpgsql AS $$
DECLARE r record;
BEGIN
FOR r IN EXECUTE 'EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT 1'
LOOP NULL; END LOOP;
END;
$$;

EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT f();

+               /*
+                * Switch to TopMemoryContext so the captured plan text survives
+                * until we print it.
+                */
+               oldcxt = MemoryContextSwitchTo(TopMemoryContext);
...
+               ExplainBeginOutput(nes);
+               ExplainPrintPlan(nes, queryDesc);
+               ExplainEndOutput(nes);
...
+               plan_info->query_text = queryDesc->sourceText ?
+                       pstrdup(queryDesc->sourceText) : pstrdup("<unknown>");

When is queryDesc freed? This seems like a memory leak.

Hi Zsolt,

Attached is v2 of the patch which fixes all three issues:

1. Error during EXPLAIN (e.g., division by zero):
- Root cause: hooks were not removed on the error path.
- Fix: wrapped EXPLAIN execution in PG_TRY/PG_FINALLY to guarantee
hook removal and cleanup regardless of errors.

2. Nested EXPLAIN crash:
- Root cause: static globals overwritten by the inner EXPLAIN.
- Fix: added a reentrancy guard — if nested tracking is already
active, the inner EXPLAIN skips hook installation entirely.

3. Memory leak (TopMemoryContext):
- Root cause: allocating captured plans in TopMemoryContext with no
cleanup on error.
- Fix: replaced TopMemoryContext with a dedicated memory context
("Nested EXPLAIN plans") that is created at the start and deleted
in PG_FINALLY — freeing everything at once on both success and
error paths.

The v2 patch passes the regression test suite (245 subtests, 0 failures)
and a comprehensive 19-test script covering the original functionality
plus the three bug scenarios, memory leak verification, and a stress
test with 50 nested statements.

Attachments:
1- v2-0001-Add-NESTED_STATEMENTS-option-to-EXPLAIN.patch
2- comprehensive_nested_statements_test_v2.sql
3- test_output_all_v2.txt

Mohamed Ali
AWS RDS

Hi,

Attached is v3 of the patch with the following improvements over v2:

New features:
- Execution Time per nested statement: each nested statement now shows
its total execution time (using query_instr->total, same source as
auto_explain). Controlled by the SUMMARY option — shown by default
with ANALYZE, hidden with SUMMARY OFF.

- Structured output formats: when using FORMAT JSON, XML, or YAML,
nested plans are now emitted as proper structured objects (with
Node Type, Plans array, typed fields, etc.) instead of flat text
strings. Each nested plan is a valid, independently parseable
document in the chosen format.

I also added new tests to the comprehensive test script to cover the
new features (now 24 tests).

One thing I'm considering for a future version: adding an option to
limit the number of captured statements or maximum nesting depth, e.g.:

EXPLAIN (ANALYZE, NESTED_STATEMENTS 10) SELECT complex_func();
-- or --
EXPLAIN (ANALYZE, NESTED_STATEMENTS, MAX_DEPTH 2) SELECT complex_func();

This would help with complex functions that execute hundreds of nested
statements. Would this be useful, or is the current behavior (capture
all) sufficient?

Attachments:
1- v3-0001-Add-NESTED_STATEMENTS-option-to-EXPLAIN.patch
2- comprehensive_nested_statements_test_v3.sql
3- test_output_all_v3.txt

Mohamed Ali
AWS RDS

Subject: [PATCH v4] Add NESTED_STATEMENTS option to EXPLAIN

Hi,

Attached is v4 of the patch adding NESTED_STATEMENTS as a core EXPLAIN
option. This version adds significant new features on top of v3

Changes since v3:
- Added SHOW_NESTED integer option to limit displayed plans
- Added Nested Statements Summary (total, max depth, timing, slowest)
- Added per-statement execution time percentage (level-1 only, %.1f)
- Added trigger detection via GetMyTriggerDepth() from trigger.c:
both BEFORE and AFTER triggers annotated with "(trigger)",
parent statements show "Trigger X: time=Y calls=Z" lines,
separate Total Trigger Time in summary (% of nested time)
- Total Nested Time and Total Trigger Time sum only level-1 statements
(deeper levels' time is already included in their level-1 parent)
- Works directly on DML with triggers and inside functions
(reveals trigger activity unreachable by built-in reporting)
- Query Identifier shown with VERBOSE (correlates with pg_stat_statements)
- Updated documentation with all new features and examples

== Feature Overview ==

1. SHOW_NESTED Option
---------------------

Controls how many nested plans are displayed. All statements are still
captured internally for the summary, but only the first N plans appear
in the output. Use SHOW_NESTED 0 for summary-only mode.

Note: This is purely a display control, it does not limit execution
or capture depth. PostgreSQL already has max_stack_depth to prevent
runaway recursion at the execution level. SHOW_NESTED addresses a
different problem: managing output size when a function legitimately
executes many statements.

EXPLAIN (ANALYZE, NESTED_STATEMENTS, SHOW_NESTED 2) SELECT my_func();

Nested Plans (showing 2 of 5):

Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM t WHERE id = 1
...
Execution Time: 0.011 ms (36.0%)

Nested Statement #2 (level 1):
Query Text: SELECT COUNT(*) FROM t WHERE id = 2
...
Execution Time: 0.010 ms (33.0%)

Nested Statements Summary:
Total: 5 statements, max depth 1
Total Execution Time: 0.353 ms
Total Nested Time: 0.030 ms (9.0% of total time)
Slowest Statement: #1 (0.011 ms, 36.0%)

SHOW_NESTED 0 shows only the summary without any individual plans.
Requires NESTED_STATEMENTS to be enabled.

2. Nested Statements Summary
----------------------------

Thanks to Ryan Booz and Lukas Fittl for the discussion at PGCon DEV
2026 which inspired the Nested Statements Summary feature.

A summary section appears after the nested plans showing key metrics:

Nested Statements Summary:
Total: 5 statements (3 direct, 2 trigger-fired), max depth 3
Total Execution Time: 1.300 ms
Total Nested Time: 1.001 ms (77.0% of total time)
Total Trigger Time: 0.125 ms (12.5% of nested time)
Slowest Statement: #2 (0.800 ms, 79.9%)

- Total Execution Time: the main query's wall-clock execution time
(same value as "Execution Time" in the main plan)
- Total Nested Time: sum of level-1 direct (non-trigger) statement
times, with percentage of total execution time
- Total Trigger Time: sum of level-1 trigger-fired statement times,
shown as percentage of nested time (only appears when triggers fire)
- Slowest Statement: identifies the bottleneck immediately
- Controlled by the SUMMARY option (on by default with ANALYZE)

The percentage answers: "What fraction of total execution time is
accounted for by the captured SQL statements?"

Example A — High % (SQL-heavy):
Total Execution Time: 50.000 ms
Total Nested Time: 48.500 ms (97.0% of total time)
→ Almost all time is in SQL. Use per-statement % to find the
slow query (e.g., a missing index on a WHERE clause).

Example B — Low % (overhead-heavy):
Total Execution Time: 10.000 ms
Total Nested Time: 0.500 ms (5.0% of total time)
→ SQL finishes in 0.5ms but the function takes 10ms total.
The gap (9.5ms) is PL/pgSQL interpreter overhead: loops,
conditionals, variable assignments, SPI context switches,
exception block setup. Consider rewriting as a single SQL
statement or reducing loop iterations.

3. Per-Statement Execution Time with Percentage
------------------------------------------------

Each level-1 nested statement shows its execution time and what fraction
of the total nested time it represents. Deeper-level statements show
only absolute time (their time is already included in their level-1
parent):

Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM products
Aggregate (actual time=0.200..0.201 rows=1.00 loops=1)
-> Seq Scan on products (...)
Execution Time: 0.201 ms (20.1%)

Nested Statement #2 (level 1):
Query Text: UPDATE products SET price = price * 1.10 WHERE ...
Update on products (actual time=0.800..0.800 rows=0.00 loops=1)
-> Seq Scan on products (...)
Execution Time: 0.800 ms (79.9%)

Percentages use one decimal place to avoid misleading rounding
(e.g., 99.8% instead of 100% when there are multiple statements).
Level-1 percentages always sum to ≤100%.

4. Trigger Detection
--------------------

Both BEFORE and AFTER trigger-fired statements are automatically
detected and annotated. Detection uses GetMyTriggerDepth() a new
C-callable getter for the existing MyTriggerDepth variable in trigger.c
(the same variable backing pg_trigger_depth() SQL function).

EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT process_order(1);

Nested Statement #1 (level 2, trigger):
Query Text: INSERT INTO audit_log (order_id, action) VALUES (...)
Insert on audit_log (actual time=0.522..0.522 rows=0.00 loops=1)
Execution Time: 0.522 ms

Nested Statement #2 (level 1):
Query Text: INSERT INTO orders VALUES (p_id, 99.99, 'new')
Insert on orders (actual time=0.842..0.842 rows=0.00 loops=1)
-> Result (actual time=0.001..0.001 rows=1.00 loops=1)
Trigger order_audit_trigger: time=0.522 calls=1
Execution Time: 1.520 ms (96.2%)

Nested Statements Summary:
Total: 4 statements (2 direct, 2 trigger-fired), max depth 2
Total Execution Time: 1.784 ms
Total Nested Time: 1.580 ms (88.6% of total time)
Total Trigger Time: 0.527 ms (33.3% of nested time)
Slowest Statement: #2 (1.520 ms, 96.2%)

Key design decisions:
- Detection uses GetMyTriggerDepth() > 0, which catches both BEFORE
and AFTER triggers (MyTriggerDepth is incremented in ExecCallTriggerFunc
before the trigger function runs, regardless of trigger timing)
- pg_trigger_depth() SQL function refactored to use the same getter
(zero behavior change, just shares the accessor)
- Trigger statements show no percentage (their time is already included
in the parent statement's time, they're not additive)
- Total Trigger Time is shown as % of nested time, telling users how
much of their SQL time is actually trigger overhead
- Summary shows "(N direct, M trigger-fired)" breakdown
- When no triggers are involved, trigger-related output is suppressed
- Nested statements that fire triggers show "Trigger X: time=Y calls=Z"
lines in their plan output (matching top-level EXPLAIN behavior)
- This also reveals trigger activity inside functions, which PostgreSQL's
built-in "Trigger X: time=Y calls=Z" reporting cannot reach (it only
reports triggers on the top-level statement)

5. Direct DML Trigger Visibility
---------------------------------

NESTED_STATEMENTS works directly on DML statements that fire triggers,
without needing to wrap anything in a function:

EXPLAIN (ANALYZE, NESTED_STATEMENTS)
UPDATE emp SET salary = salary * 1.10 WHERE salary < 65000;

Nested Statement #1 (level 2, trigger):
Query Text: INSERT INTO notifications VALUES (...)
...
Execution Time: 0.415 ms

Nested Statement #2 (level 1, trigger):
Query Text: INSERT INTO emp_audit VALUES (OLD.id, OLD.salary, NEW.salary)
...
Execution Time: 1.221 ms

Nested Statements Summary:
Total: 4 statements (0 direct, 4 trigger-fired), max depth 2
Total Execution Time: 5.440 ms
Total Trigger Time: 1.692 ms
Slowest Statement: #2 (1.221 ms)

This reveals cascading trigger chains: the UPDATE fires an audit
trigger (level 1), which inserts into emp_audit, which fires a
notification trigger (level 2). Users can immediately see why their
simple UPDATE is slow.

6. Query Identifier Integration (pg_stat_statements)
-----------------------------------------------------

When VERBOSE is enabled and compute_query_id is active, each nested
statement shows its Query Identifier. Repeated queries (same SQL
with different parameters) share the same identifier, allowing users
to correlate nested plans with pg_stat_statements entries:

SET compute_query_id = on;
EXPLAIN (ANALYZE, NESTED_STATEMENTS, VERBOSE, COSTS OFF)
SELECT process_orders();

Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM orders
Aggregate (...)
Query Identifier: 213668903401070912
Execution Time: 0.012 ms (0.2%)

Nested Statement #3 (level 2):
Query Text: UPDATE orders SET total = total * (1 - p_pct/100)
WHERE id = p_id
Update on orders (...)
Query Identifier: -4236462531438235649
Trigger audit_trig: time=1.110 calls=1
Execution Time: 1.172 ms (15.2%)

Users can then query: SELECT * FROM pg_stat_statements
WHERE queryid = -4236462531438235649;

This requires no additional code — it works because ExplainPrintPlan
already shows Query Identifier when VERBOSE is enabled, and SPI
computes queryIds for nested statements when compute_query_id is on.

== Implementation Notes ==

- Trigger detection uses GetMyTriggerDepth() a new getter function
added to trigger.c that exposes the existing MyTriggerDepth variable.
pg_trigger_depth() SQL function refactored to use the same getter.
Detects both BEFORE and AFTER triggers with a single check.
- Each nested statement's plan includes ExplainPrintTriggers() output,
showing which triggers it fired (matches top-level EXPLAIN behavior)
- Total Nested Time only sums level-1 direct (non-trigger) statements;
deeper levels show absolute time but are not added to the total
(their time is already included in their level-1 parent's time)
- Total Trigger Time similarly sums only level-1 trigger statements
to avoid overcounting with cascading triggers
- SHOW_NESTED controls display only; all statements are still captured
for accurate summary statistics regardless of the display limit
- The show_nested field defaults to -1 (show all); 0 means summary only
- Structured formats (JSON/XML/YAML) include Execution Time as a typed
numeric field inside each nested plan's structure
- This feature reveals trigger activity inside functions that PostgreSQL's
built-in trigger reporting ("Trigger X: time=Y calls=Z") cannot reach

== Test Suite ==

The patch includes a comprehensive test script with 41 test cases
covering all features, edge cases, and error handling. The full
output is attached so reviewers can see actual behavior without
needing to apply the patch, and to help identify any test cases
I may have missed:

comprehensive_nested_statements_test_v4.sql (test script)
test_output_all_v4.txt (full output)

Test cases:
1. Validation (NESTED_STATEMENTS requires ANALYZE)
2. Simple PL/pgSQL function (all level 1)
3. PERFORM pattern (creates deeper nesting levels)
4. Expression assignment (stays at same level)
5. Side-by-side comparison of both patterns
6. SQL function nesting (true SQL nesting)
7. Three-level chain with PERFORM
8. Recursive function (increasing levels)
9. Exception handling blocks
10. No nested statements (plain query)
11. Trigger-fired nested statements (with detection)
12. Combined with VERBOSE and BUFFERS
13. Statement numbering = completion order (triggers demo)
14. BEGIN/ROLLBACK safety pattern
15. Error during EXPLAIN does not crash (Bug 1 fix)
16. Nested EXPLAIN does not crash (Bug 2 fix)
17. Memory context cleanup (Bug 3 fix)
18. Memory context does not grow across repeated calls
19. Stress test - 50 nested statements
20. Execution Time per nested statement (SUMMARY default)
21. SUMMARY OFF hides timing, percentages, and summary section
22. Structured output - JSON format
23. Structured output - XML format
24. Structured output - YAML format
25. SHOW_NESTED - limit displayed plans
26. SHOW_NESTED 0 - summary only
27. SHOW_NESTED validation (requires NESTED_STATEMENTS)
28. Nested Statements Summary with percentages
29. Statement timeout - hooks cleaned up
30. Dynamic SQL - query text captured correctly
31. Infinite recursion - graceful error (max_stack_depth protects
execution; hooks cleaned up via PG_FINALLY, server continues)
32. auto_explain compatibility
33. Deep nesting (20 levels)
34. All EXPLAIN options combined with SHOW_NESTED
35. Performance - zero overhead when disabled
36. Interpreting Total Nested Time percentage
37. Multiple triggers on separate tables
38. Direct DML with triggers (BEFORE + AFTER, cascading, rejection)
39. BEFORE and AFTER triggers in function context
40. Query Identifier integration (pg_stat_statements)
41. Level-1 only counting (no double-counting with deep nesting)

== Open Questions ==

1. Should the per-statement percentage be available in JSON format as
a separate "Execution Time Percentage" field? Currently it's only
shown in TEXT format and the summary.

2. Should there be a MAX_DEPTH option to limit capture by nesting
level (complementing SHOW_NESTED which limits by count)?

Mohamed Ali
AWS RDS

+<programlisting>
+EXPLAIN (ANALYZE, NESTED_STATEMENTS, FORMAT JSON) SELECT my_function();

and

+   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.0

Are you sure this is correct? My expectation would be for FORMAT JSON to output a valid, usable JSON document. E.g.:

bin/psql -X -t -A -d db -c "EXPLAIN (FORMAT JSON) SELECT ..." > file.json

writes a valid json file which I can then parse with any json parser.

If I do the same with NESTED_STATEMENTS, I get an invalid json. It's not only a concatenation of multiple json documents, but also includes additional completely non-json text in it. It seems difficult to parse/use.

Same goes for XML/YAML.

+			if (!is_trigger && nested_exec_level == 1 &&
+				stmt_time > nested_slowest_time)
+			{
+				nested_slowest_time = stmt_time;
+				nested_slowest_num = nested_total_count;
+			}

Why is the slowest statement check limited to nesting level 1?

For example, see the following test case where it doesn't display any slowest statement:

CREATE TABLE big(n int);
INSERT INTO big SELECT g FROM generate_series(1, 200000) g;
CREATE TABLE t_a(id int primary key);
CREATE TABLE t_log(id int);
INSERT INTO t_a VALUES (1);
CREATE OR REPLACE FUNCTION slow_trig() RETURNS trigger LANGUAGE plpgsql AS $$
DECLARE r bigint;
BEGIN
SELECT count(*) FROM big a, generate_series(1, 40) b INTO r;
INSERT INTO t_log VALUES (NEW.id);
RETURN NEW;
END;
$$;
CREATE TRIGGER slow_trigger AFTER UPDATE ON t_a
FOR EACH ROW EXECUTE FUNCTION slow_trig();
EXPLAIN (ANALYZE, NESTED_STATEMENTS, COSTS OFF, TIMING ON)
UPDATE t_a SET id = id WHERE id = 1;

Trigger time calculation also doesn't work for multiple nesting levels, see:

CREATE TABLE t(i int);
CREATE FUNCTION trg() RETURNS trigger LANGUAGE plpgsql AS $$
BEGIN PERFORM pg_sleep(0.05); RETURN NEW; END $$;
CREATE TRIGGER trg BEFORE INSERT ON t FOR EACH ROW EXECUTE FUNCTION trg();
CREATE FUNCTION f() RETURNS void LANGUAGE plpgsql AS $$
BEGIN INSERT INTO t VALUES(1); END $$;
EXPLAIN (ANALYZE, NESTED_STATEMENTS, COSTS OFF, TIMING OFF, BUFFERS OFF) SELECT f();

And staying with the topic of triggers, are you sure that all statements that are executed within triggers should get a trigger label? Wouldn't it be better to track only directly trigger-executed statements?

+   <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.

Wouldn't start-time ordering be better rather than completion? Right now, it includes children before the caller, which could look confusing. With a multi level difference between statement it is clearer, but if a level 2 statement follows a level 1 statement, my first thought that the level 1 statement called the level 2. But it didn't, the next level 1 did.

Hi Zsolt,

Attached is v5 of the patch.

Regarding the trigger label scope question: the `(trigger)` annotation
uses `GetMyTriggerDepth() > 0`, which labels ALL statements inside any
trigger context (including cascading triggers). The nesting level
already distinguishes direct vs cascade (level 2 = direct, level 3+ =
cascade).

Regarding statement ordering: v5 switches from completion order to
start-time (chronological) order. The previous versions used completion
order because it naturally matches how the executor hooks fire and is
what auto_explain uses internally. However, I agree with your feedback
that start-time order is better for users reading the output — parents
appear before their children, which reads more naturally top-to-bottom.
See the detailed section below.

Changes since v4:
- Valid structured output: JSON, XML, and YAML now produce a single
parseable document with nested plans as structured sub-objects
inside a "Nested Plans" array
- Execution Time Percentage now appears in all structured formats
(JSON/XML/YAML) inside the Query object, next to Execution Time
- Start-time (chronological) ordering: nested statements displayed
in the order they started, not completion order. Parents appear
before their children. Statement numbers are sequential.
- SECURITY DEFINER protection: nested plans hidden from unprivileged
users inside SECURITY DEFINER functions. Only superusers and
pg_read_all_stats members can see them. NOTICE emitted explaining
why plans are not shown.
- Added NOTICE when >1000 nested statements captured without
SHOW_NESTED (warns about per-row SQL function volume, suggests
SHOW_NESTED 0 or SHOW_NESTED N), NOTICE suppressed when
SHOW_NESTED is already set,
documented per-row function behavior.
- Added IO option inheritance (INSTRUMENT_IO + nes->io)
- MEMORY option documented as not applicable to nested plans
(planning handled by SPI internally)
- Added DEBUG1 log on reentrancy (nested EXPLAIN NESTED_STATEMENTS)
- Added SETTINGS option inheritance (reveals when functions internally
change planner settings like enable_seqscan)
- Fixed: Slowest Statement now tracks across ALL levels and types
(previously missed trigger-only scenarios)
- Fixed: Total Trigger Time now sums ALL trigger statements regardless
of nesting level (previously missed triggers at level 2+)
- Tested parallel query interaction (6 scenarios, no crashes).
- Tested edge cases: prepared statements (SPI plan caching),
nested cursors (FOR loop + explicit), cross-database (dblink),
DDL inside functions.
- Confirmed multi-language support: PL/pgSQL, PL/Tcl, PL/Perl all
captured correctly (any language using SPI works)
- Test suite expanded from 41 to 55 cases

== New in v5: Valid Structured Output (JSON/XML/YAML) ==

Previously, FORMAT JSON/XML/YAML with NESTED_STATEMENTS produced a mix
of structured blocks and plain text — not a single valid document.
This has been completely reworked. The output is now a single valid
parseable document in all structured formats, with nested plans as
structured sub-objects and "Execution Time Percentage" included for
level-1 non-trigger statements.

== New in v5: High-Volume NOTICE ==

When a query calls a SQL function per-row (e.g.,
SELECT func(id) FROM large_table), each invocation generates a
separate nested statement capture. This can produce thousands of
captures for large result sets.

To protect users who aren't aware of this behavior, a NOTICE is
emitted when more than 1000 nested statements are captured and
SHOW_NESTED has not been set:

NOTICE: 1500 nested statements captured (per-row SQL function
calls can produce high counts)
HINT: Use SHOW_NESTED 0 for summary only, or SHOW_NESTED N to
display the first N plans.

The NOTICE is suppressed when SHOW_NESTED is explicitly set (the user
already knows about volume control). The threshold (1000) is a
compile-time constant.

Memory is already bounded by SHOW_NESTED — only the first N plans are
stored as text. Beyond that limit, only counters and timing are
accumulated (per statement).

== Parallel Query Interaction ==

Tested and confirmed safe with parallel workers:

- Executor hooks are process-local (leader only). Parallel workers
have separate executor contexts and do not inherit hooks.
- PL/pgSQL functions (PARALLEL UNSAFE) always run in the leader —
all nested statements captured correctly.
- SQL functions called per-row in a parallel query: if evaluated in
the leader (target list expressions after Gather), all captured.
If pushed below Gather into workers (WHERE clause filter), only
leader executions are captured. Same limitation as auto_explain.
- No crashes in any parallel scenario.

== Multi-Language Support via SPI ==

This feature works with ANY procedural language, not just PL/pgSQL.
The mechanism is the Server Programming Interface (SPI):

PL function body
-> SPI_connect()
-> SPI_execute("SELECT ...")
-> ExecutorStart() <- the hook increments nesting level
-> ExecutorRun() <- query executes
-> ExecutorEnd() <- the hook captures the plan
-> SPI_finish()

Every PL language uses SPI to run SQL inside the server:
- PL/pgSQL: automatic (every SQL statement goes through SPI)
- PL/Perl: spi_exec_query("SELECT ...")
- PL/Tcl: spi_exec {SELECT ...}
- PL/Python: plpy.execute("SELECT ...")

Since the hooks are installed at the executor level (below SPI), they
capture SQL from all languages identically. Tested and confirmed with
PL/pgSQL, PL/Tcl, and PL/Perl -- all produce the same nested statement
output. A separate test script (test_pl_languages.sql) demonstrates
this with side-by-side output from all three languages. This script
is attached alongside the patch.

This is the same architecture used by auto_explain -- it also hooks
the executor and captures plans from any SPI-based language.

== New in v5: SECURITY DEFINER Protection ==

Nested plans inside SECURITY DEFINER functions are hidden from
unprivileged users. When the effective user differs from the session
user (indicating a SECURITY DEFINER context), nested statement capture
is skipped entirely unless the session user is a superuser or holds
the pg_read_all_stats role.

A NOTICE is emitted explaining why nested plans are not shown:

NOTICE: nested statements hidden: executed inside SECURITY DEFINER function
HINT: Only superusers and roles with pg_read_all_stats can view
nested plans inside SECURITY DEFINER functions.

This prevents unprivileged users from inspecting query text and plan
details of functions whose internals they should not see. Superusers
and pg_read_all_stats members always have full visibility. The
pg_read_all_stats role is used because it's the same role that
pg_stat_statements uses to gate query text visibility (pg_monitor
members are also covered transitively).

== Edge Cases Tested ==

- Prepared statements: SPI plan caching (custom → generic plan
transition) does not affect capture. Plans captured regardless
of cache state.
- Nested cursors: FOR loop cursors generate one nested statement per
cursor query (not per row). Explicit OPEN/FETCH/CLOSE cursors
captured at CLOSE time.
- Cross-database queries (dblink): Remote SQL executes in a separate
backend — not captured. Only local statements visible. Same
limitation as auto_explain.
- DDL inside functions: CREATE/DROP TABLE go through ProcessUtility
(not executor) — not captured. DML on the created table IS
captured. No crash when DDL is mixed with DML.

== Test Suite (55 cases) ==

comprehensive_nested_statements_test_v5.sql (test script)
test_output_all_v5.txt (full output)

New tests in v5:
42. Parallel — nested plans inside parallel context
43. Parallel — nested PERFORM with parallel inner SQL
44. Parallel — INSERT...SELECT with trigger + parallel source
45. Parallel — PARALLEL SAFE function in WHERE (worker execution)
46. High-volume NOTICE (per-row function calls)
47. Prepared statements (SPI plan caching)
48. Security-definer function (privilege protection: superuser,
regular user, pg_read_all_stats, pg_monitor, INVOKER)
49. Nested cursors (FOR loop and explicit OPEN/FETCH/CLOSE)
50. Cross-database queries (dblink) — known limitation
51. DDL inside function (CREATE/DROP TEMP TABLE)
52. Reentrancy DEBUG log (nested EXPLAIN NESTED_STATEMENTS)
53. SETTINGS inheritance (function with internal SET)
54. Slowest statement — trigger-only scenario
55. Trigger time — multi-level nesting

Thanks,
Mohamed Ali

At 2026-06-02 11:01:26, "Mohamed ALi" <moali.pg@gmail.com> wrote:

Attached is v5 of the patch.

Regarding the trigger label scope question: the `(trigger)` annotation
uses `GetMyTriggerDepth() > 0`, which labels ALL statements inside any
trigger context (including cascading triggers). The nesting level
already distinguishes direct vs cascade (level 2 = direct, level 3+ =
cascade).

Regarding statement ordering: v5 switches from completion order to
start-time (chronological) order. The previous versions used completion
order because it naturally matches how the executor hooks fire and is
what auto_explain uses internally. However, I agree with your feedback
that start-time order is better for users reading the output — parents
appear before their children, which reads more naturally top-to-bottom.
See the detailed section below.

Changes since v4:

Hi,
I have some review feedback on the v5 patch.

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 112c17b0d64..3392fceae34 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
...
+					else if (es->format == EXPLAIN_FORMAT_YAML)
+					{
+						/* Find "Execution Time:" line and append percentage after it */
+						char *et = strstr(info->plan_text, "Execution Time:");
+						if (et)
+						{
+							StringInfoData newbuf;
+							/* Find end of line */
+							char *eol = et;
+							while (*eol && *eol != '\n')
+								eol++;
+
+							initStringInfo(&newbuf);
+							appendBinaryStringInfo(&newbuf, info->plan_text,
+												   eol - info->plan_text);
+							appendStringInfo(&newbuf,
+											 "\n  Execution Time Percentage: %.1f",
+											 pct);
...

The patch works by first emitting the full JSON/XML/YAML plan string, then parsing,
slicing and stitching it via strstr, strchr and pointer arithmetic to inject additional fields,
alongside a few hardcoded special cases. I don’t find this implementation elegant.
When dealing with YAML output, this subtle design weakness can cause problems when locating where to insert new content in the generated YAML text.
For instance, consider a table named `public.Execution Time: T`.

CREATE TABLE "public.Execution Time: T" (id int);
INSERT INTO "public.Execution Time: T" VALUES (1);
CREATE FUNCTION f() RETURNS bigint AS $$
DECLARE r bigint;
BEGIN SELECT count(*) INTO r FROM "public.Execution Time: T"; RETURN r; END;
$$ LANGUAGE plpgsql;
EXPLAIN (FORMAT YAML, ANALYZE, NESTED_STATEMENTS, SUMMARY ON) SELECT f();

The line `Execution Time Percentage: 100.0` would then get inserted into the incorrect position.
I may be nitpicking, of course — table names of that form are virtually nonexistent in real-world usage.
Still, this approach feels somewhat hacky.

Best regards,

--

Yilin Zhang