Re: [PATCH] Add NESTED_STATEMENTS option to EXPLAIN

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