public inbox for [email protected]
help / color / mirror / Atom feedFrom: Mohamed ALi <[email protected]>
To: Zsolt Parragi <[email protected]>
Cc: [email protected]
Subject: Re: [PATCH] Add NESTED_STATEMENTS option to EXPLAIN
Date: Thu, 21 May 2026 13:51:58 -0700
Message-ID: <CAGnOmWoyrffJeJ9uz6wkB0arO4BPDMRK-YemicT1Prp4umtrJA@mail.gmail.com> (raw)
In-Reply-To: <CAGnOmWqNg0e4JDnti_B5PTfbpbFR18KkmczmrDKVXw-OMirbNg@mail.gmail.com>
References: <CAGnOmWp96ZHNyQ+4YijH9wqc=CcGm8cuBq9rRCXsaz0SO86tLg@mail.gmail.com>
<CAN4CZFM+b5mD4o=5WzSQjBsZOeeZaRfUPKeFgif4bwsccOLaHA@mail.gmail.com>
<CAGnOmWofX8ru+AnOTkeLjLF6eMjFUsQLYzV_sf1D70FqNHAApQ@mail.gmail.com>
<CAGnOmWqNg0e4JDnti_B5PTfbpbFR18KkmczmrDKVXw-OMirbNg@mail.gmail.com>
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
============================================================================
NESTED_STATEMENTS Feature - Comprehensive Test Suite
============================================================================
This test suite demonstrates:
1. Validation (NESTED_STATEMENTS requires ANALYZE)
2. Simple PL/pgSQL function (all level 1)
3. PERFORM pattern (creates deeper nesting levels)
4. Expression assignment pattern (stays at same level)
5. Comparison: PERFORM vs expression assignment
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
12. Combined with VERBOSE and BUFFERS options
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. Execution Time hidden with SUMMARY OFF
22. Structured output - JSON format
23. Structured output - XML format
24. Structured output - YAML format
-- ============================================================================
psql:comprehensive_nested_statements_test_v3.sql:44: NOTICE: table "products" does not exist, skipping
DROP TABLE
CREATE TABLE
INSERT 0 3
============================================================================
TEST 1: Validation - NESTED_STATEMENTS requires ANALYZE
============================================================================
Expected: ERROR message
psql:comprehensive_nested_statements_test_v3.sql:61: ERROR: EXPLAIN option NESTED_STATEMENTS requires ANALYZE
============================================================================
TEST 2: Simple PL/pgSQL Function - All Statements at Level 1
============================================================================
Purpose: SQL statements in a single function all execute at level 1
because they run sequentially in the same executor context.
CREATE FUNCTION
Expected: All 4 statements at level 1
QUERY PLAN
-------------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=170 read=16
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM products
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on products (actual rows=3.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: INSERT INTO products VALUES (10, 'Temp', 1, 'Temp')
Insert on products (actual rows=0.00 loops=1)
Buffers: shared hit=1
-> Result (actual rows=1.00 loops=1)
Nested Statement #3 (level 1):
Query Text: UPDATE products SET price = price + 1 WHERE id = 1
Update on products (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on products (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 3
Buffers: shared hit=1
Nested Statement #4 (level 1):
Query Text: DELETE FROM products WHERE id = 10
Delete on products (actual rows=0.00 loops=1)
Buffers: shared hit=2
-> Seq Scan on products (actual rows=1.00 loops=1)
Filter: (id = 10)
Rows Removed by Filter: 3
Buffers: shared hit=1
(35 rows)
============================================================================
TEST 3: PERFORM Pattern - Creates Deeper Nesting Levels
============================================================================
Purpose: PERFORM func() creates a new executor call (SELECT func()),
so statements inside the called function run at a deeper level.
How it works internally:
PERFORM func() → executes "SELECT func()" → ExecutorRun increments level
→ func() body runs its SQL at the elevated level
CREATE FUNCTION
CREATE FUNCTION
Expected:
Statement #1 (level 1): SELECT COUNT in outer_perform
Statement #2 (level 2): UPDATE in inner_perform
Statement #3 (level 2): INSERT in inner_perform
Statement #4 (level 2): DELETE in inner_perform
Statement #5 (level 1): SELECT inner_perform() [the PERFORM call]
Statement #6 (level 1): UPDATE in outer_perform
QUERY PLAN
---------------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=58 read=1
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM products
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on products (actual rows=3.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 2):
Query Text: UPDATE products SET price = price + 1 WHERE id = 2
Update on products (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on products (actual rows=1.00 loops=1)
Filter: (id = 2)
Rows Removed by Filter: 2
Buffers: shared hit=1
Nested Statement #3 (level 2):
Query Text: INSERT INTO products VALUES (20, 'Inner', 50, 'Test')
Insert on products (actual rows=0.00 loops=1)
Buffers: shared hit=1
-> Result (actual rows=1.00 loops=1)
Nested Statement #4 (level 2):
Query Text: DELETE FROM products WHERE id = 20
Delete on products (actual rows=0.00 loops=1)
Buffers: shared hit=2
-> Seq Scan on products (actual rows=1.00 loops=1)
Filter: (id = 20)
Rows Removed by Filter: 3
Buffers: shared hit=1
Nested Statement #5 (level 1):
Query Text: SELECT inner_perform()
Result (actual rows=1.00 loops=1)
Buffers: shared hit=6
Nested Statement #6 (level 1):
Query Text: UPDATE products SET price = price - 1 WHERE id = 2
Update on products (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on products (actual rows=1.00 loops=1)
Filter: (id = 2)
Rows Removed by Filter: 2
Buffers: shared hit=1
(49 rows)
============================================================================
TEST 4: Expression Assignment (result := func()) - Same Level
============================================================================
Purpose: result := func() evaluates the function as an expression via
ExecEvalFunc WITHOUT creating a new executor call. Statements
inside the called function run at the SAME level as the caller.
How it works internally:
result := func() → ExecEvalFunc(func) → NO new ExecutorRun
→ func() body runs its SQL at the SAME level as caller
CREATE FUNCTION
CREATE FUNCTION
Expected: ALL statements at level 1 (no deeper nesting)
Statement #1 (level 1): SELECT COUNT in outer_expr
Statement #2 (level 1): SELECT SUM in inner_expr ← same level!
Statement #3 (level 1): UPDATE in inner_expr ← same level!
Statement #4 (level 1): DELETE in outer_expr
QUERY PLAN
------------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=191 read=9
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM products
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on products (actual rows=3.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: SELECT SUM(price) FROM products
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on products (actual rows=3.00 loops=1)
Buffers: shared hit=1
Nested Statement #3 (level 1):
Query Text: UPDATE products SET price = price + 1 WHERE id = 3
Update on products (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on products (actual rows=1.00 loops=1)
Filter: (id = 3)
Rows Removed by Filter: 2
Buffers: shared hit=1
Nested Statement #4 (level 1):
Query Text: DELETE FROM products WHERE price > 9999
Delete on products (actual rows=0.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on products (actual rows=0.00 loops=1)
Filter: (price > '9999'::numeric)
Rows Removed by Filter: 3
Buffers: shared hit=1
(36 rows)
============================================================================
TEST 5: PERFORM vs Expression Assignment - Side by Side
============================================================================
Purpose: Same inner function called two different ways to show the
nesting level difference.
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
--- Via PERFORM (expect level 2 for inner SELECT): ---
QUERY PLAN
-------------------------------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=25 read=2
Nested Plans:
Nested Statement #1 (level 2):
Query Text: SELECT COUNT(*) FROM products WHERE category = 'Electronics'
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on products (actual rows=2.00 loops=1)
Filter: (category = 'Electronics'::text)
Rows Removed by Filter: 1
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: SELECT shared_inner()
Result (actual rows=1.00 loops=1)
Buffers: shared hit=19 read=2
(18 rows)
--- Via expression assignment (expect level 1 for inner SELECT): ---
QUERY PLAN
-------------------------------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=1
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM products WHERE category = 'Electronics'
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on products (actual rows=2.00 loops=1)
Filter: (category = 'Electronics'::text)
Rows Removed by Filter: 1
Buffers: shared hit=1
(13 rows)
Notice: Same function, different nesting levels depending on call pattern.
============================================================================
TEST 6: SQL Functions - True SQL Execution Nesting
============================================================================
Purpose: SQL functions execute DURING the parent query, creating true
SQL nesting where inner functions complete before outer.
psql:comprehensive_nested_statements_test_v3.sql:253: NOTICE: table "t1" does not exist, skipping
psql:comprehensive_nested_statements_test_v3.sql:253: NOTICE: table "t2" does not exist, skipping
psql:comprehensive_nested_statements_test_v3.sql:253: NOTICE: table "t3" does not exist, skipping
DROP TABLE
CREATE TABLE
CREATE TABLE
CREATE TABLE
INSERT 0 1
INSERT 0 1
INSERT 0 1
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
Expected: Deepest-first execution order (3→2→1)
Statement #1 (level 3): SELECT from t3 (sql_level3)
Statement #2 (level 2): SELECT from t2 (sql_level2)
Statement #3 (level 1): SELECT from t1 (plpgsql_sql_caller)
QUERY PLAN
-----------------------------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=30
Nested Plans:
Nested Statement #1 (level 3):
Query Text:
SELECT data FROM t3 WHERE id = 1;
Seq Scan on t3 (actual rows=1.00 loops=1)
Filter: (id = 1)
Buffers: shared hit=1
Nested Statement #2 (level 2):
Query Text:
SELECT data || '+' || sql_level3() FROM t2 WHERE id = 1;
Seq Scan on t2 (actual rows=1.00 loops=1)
Filter: (id = 1)
Buffers: shared hit=8
Nested Statement #3 (level 1):
Query Text: SELECT data || '+' || sql_level2() FROM t1 WHERE id = 1
Seq Scan on t1 (actual rows=1.00 loops=1)
Filter: (id = 1)
Buffers: shared hit=15
(26 rows)
============================================================================
TEST 7: Three-Level PL/pgSQL Chain (via PERFORM)
============================================================================
Purpose: Each PERFORM adds one executor level
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
Expected:
Statement #1 (level 1): SELECT COUNT(*) FROM products
Statement #2 (level 2): SELECT COUNT(*) WHERE id = 1
Statement #3 (level 3): SELECT COUNT(*) WHERE category = Books
Statement #4 (level 2): SELECT chain_level3()
Statement #5 (level 1): SELECT chain_level2()
QUERY PLAN
----------------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=18
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM products
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on products (actual rows=3.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 2):
Query Text: SELECT COUNT(*) FROM products WHERE id = 1
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on products (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 2
Buffers: shared hit=1
Nested Statement #3 (level 3):
Query Text: SELECT COUNT(*) FROM products WHERE category = 'Books'
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on products (actual rows=1.00 loops=1)
Filter: (category = 'Books'::text)
Rows Removed by Filter: 2
Buffers: shared hit=1
Nested Statement #4 (level 2):
Query Text: SELECT chain_level3()
Result (actual rows=1.00 loops=1)
Buffers: shared hit=1
Nested Statement #5 (level 1):
Query Text: SELECT chain_level2()
Result (actual rows=1.00 loops=1)
Buffers: shared hit=8
(39 rows)
============================================================================
TEST 8: Recursive Function - Increasing Nesting Levels
============================================================================
Purpose: Recursive PERFORM calls increase the nesting level each time
psql:comprehensive_nested_statements_test_v3.sql:341: NOTICE: table "counter_log" does not exist, skipping
DROP TABLE
CREATE TABLE
CREATE FUNCTION
Expected:
Statement #1 (level 1): INSERT with n=3
Statement #2 (level 2): INSERT with n=2
Statement #3 (level 3): INSERT with n=1
+ PERFORM calls at levels 2 and 1
QUERY PLAN
----------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=39 read=2 dirtied=1 written=1
Nested Plans:
Nested Statement #1 (level 1):
Query Text: INSERT INTO counter_log VALUES (n, n * 10)
Insert on counter_log (actual rows=0.00 loops=1)
Buffers: shared dirtied=1 written=1
-> Result (actual rows=1.00 loops=1)
Nested Statement #2 (level 2):
Query Text: INSERT INTO counter_log VALUES (n, n * 10)
Insert on counter_log (actual rows=0.00 loops=1)
Buffers: shared hit=1
-> Result (actual rows=1.00 loops=1)
Nested Statement #3 (level 3):
Query Text: INSERT INTO counter_log VALUES (n, n * 10)
Insert on counter_log (actual rows=0.00 loops=1)
Buffers: shared hit=1
-> Result (actual rows=1.00 loops=1)
Nested Statement #4 (level 2):
Query Text: SELECT recursive_func(n - 1)
Result (actual rows=1.00 loops=1)
Buffers: shared hit=1
Nested Statement #5 (level 1):
Query Text: SELECT recursive_func(n - 1)
Result (actual rows=1.00 loops=1)
Buffers: shared hit=2
(32 rows)
============================================================================
TEST 9: Exception Handling - Statements in BEGIN/EXCEPTION Blocks
============================================================================
Purpose: Verify statements in exception handlers are captured
psql:comprehensive_nested_statements_test_v3.sql:375: NOTICE: table "safe_table" does not exist, skipping
DROP TABLE
CREATE TABLE
INSERT 0 1
CREATE FUNCTION
Expected:
- UPDATE (level 1): initial update
- UPDATE (level 1): recovery in exception handler
- The failed INSERT is rolled back and may not appear
QUERY PLAN
-----------------------------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=23
Nested Plans:
Nested Statement #1 (level 1):
Query Text: UPDATE safe_table SET data = 'updated' WHERE id = 1
Update on safe_table (actual rows=0.00 loops=1)
Buffers: shared hit=4
-> Index Scan using safe_table_pkey on safe_table (actual rows=1.00 loops=1)
Index Cond: (id = 1)
Index Searches: 1
Buffers: shared hit=2
Nested Statement #2 (level 1):
Query Text: UPDATE safe_table SET data = 'recovered' WHERE id = 1
Update on safe_table (actual rows=0.00 loops=1)
Buffers: shared hit=4
-> Index Scan using safe_table_pkey on safe_table (actual rows=1.00 loops=1)
Index Cond: (id = 1)
Index Searches: 1
Buffers: shared hit=2
(22 rows)
============================================================================
TEST 10: No Nested Statements - Plain Query
============================================================================
Purpose: When no nested statements execute, no "Nested Plans:" section
Expected: Normal EXPLAIN output, no Nested Plans section
QUERY PLAN
-------------------------------------------------
Seq Scan on products (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 2
Buffers: shared hit=1
(4 rows)
============================================================================
TEST 11: Trigger-Fired Nested Statements
============================================================================
Purpose: Triggers fire DURING the triggering statement, creating
deeper nesting. Note: trigger statements may appear BEFORE
their parent (completion order, not start order).
psql:comprehensive_nested_statements_test_v3.sql:432: NOTICE: table "orders" does not exist, skipping
DROP TABLE
psql:comprehensive_nested_statements_test_v3.sql:433: NOTICE: table "audit_log" does not exist, skipping
DROP TABLE
CREATE TABLE
CREATE TABLE
CREATE FUNCTION
CREATE TRIGGER
CREATE FUNCTION
Expected:
- INSERT INTO audit_log (level 2): trigger from INSERT
- INSERT INTO orders (level 1): the triggering statement
- INSERT INTO audit_log (level 2): trigger from UPDATE
- UPDATE orders (level 1): the triggering statement
Note: Level 2 statements appear before level 1 because triggers
complete (ExecutorEnd) before the parent statement completes.
QUERY PLAN
---------------------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=68 read=1 dirtied=4 written=3
Nested Plans:
Nested Statement #1 (level 2):
Query Text: INSERT INTO audit_log (order_id, action)
VALUES (NEW.id, TG_OP || ': ' || NEW.status)
Insert on audit_log (actual rows=0.00 loops=1)
Buffers: shared dirtied=1 written=1
-> Result (actual rows=1.00 loops=1)
Nested Statement #2 (level 1):
Query Text: INSERT INTO orders VALUES (p_id, 99.99, 'new')
Insert on orders (actual rows=0.00 loops=1)
Buffers: shared hit=14 read=1 dirtied=3 written=2
-> Result (actual rows=1.00 loops=1)
Nested Statement #3 (level 2):
Query Text: INSERT INTO audit_log (order_id, action)
VALUES (NEW.id, TG_OP || ': ' || NEW.status)
Insert on audit_log (actual rows=0.00 loops=1)
Buffers: shared hit=1
-> Result (actual rows=1.00 loops=1)
Nested Statement #4 (level 1):
Query Text: UPDATE orders SET status = 'processed' WHERE id = p_id
Update on orders (actual rows=0.00 loops=1)
Buffers: shared hit=5
-> Index Scan using orders_pkey on orders (actual rows=1.00 loops=1)
Index Cond: (id = 1)
Index Searches: 1
Buffers: shared hit=2
(33 rows)
============================================================================
TEST 12: NESTED_STATEMENTS with VERBOSE and BUFFERS
============================================================================
Purpose: VERBOSE and BUFFERS options are inherited by nested plans
CREATE FUNCTION
Expected: Schema-qualified names (public.products) and Output columns
QUERY PLAN
-----------------------------------------------------------------------------------------------------
Result (cost=0.00..0.26 rows=1 width=4) (actual rows=1.00 loops=1)
Output: verbose_func()
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM products
Aggregate (cost=17.88..17.89 rows=1 width=8) (actual rows=1.00 loops=1)
Output: count(*)
Buffers: shared hit=1
-> Seq Scan on public.products (cost=0.00..16.30 rows=630 width=0) (actual rows=3.00 loops=1)
Output: id, name, price, category
Buffers: shared hit=1
(14 rows)
============================================================================
TEST 13: Statement Numbering Shows Completion Order
============================================================================
Purpose: Statement #N reflects when a statement FINISHES (ExecutorEnd),
not when it starts. This is most visible with triggers:
Timeline for INSERT with an AFTER trigger:
1. Parent INSERT starts executing
2. Trigger fires → trigger INSERT starts → trigger INSERT FINISHES → gets #1
3. Parent INSERT FINISHES → gets #2
The trigger statement finishes INSIDE the parent, so it gets a lower number.
psql:comprehensive_nested_statements_test_v3.sql:515: NOTICE: table "demo_orders" does not exist, skipping
DROP TABLE
psql:comprehensive_nested_statements_test_v3.sql:516: NOTICE: table "demo_log" does not exist, skipping
DROP TABLE
CREATE TABLE
CREATE TABLE
CREATE FUNCTION
CREATE TRIGGER
CREATE FUNCTION
Expected numbering (completion order):
#1 (level 2): INSERT INTO demo_log ← trigger finishes first
#2 (level 1): INSERT INTO demo_orders (Widget) ← parent finishes second
#3 (level 2): INSERT INTO demo_log ← second trigger finishes
#4 (level 1): INSERT INTO demo_orders (Gadget) ← second parent finishes
QUERY PLAN
--------------------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=36 dirtied=2 written=2
Nested Plans:
Nested Statement #1 (level 2):
Query Text: INSERT INTO demo_log VALUES ('order placed: ' || NEW.item)
Insert on demo_log (actual rows=0.00 loops=1)
Buffers: shared dirtied=1 written=1
-> Result (actual rows=1.00 loops=1)
Nested Statement #2 (level 1):
Query Text: INSERT INTO demo_orders VALUES (1, 'Widget')
Insert on demo_orders (actual rows=0.00 loops=1)
Buffers: shared dirtied=1 written=1
-> Result (actual rows=1.00 loops=1)
Nested Statement #3 (level 2):
Query Text: INSERT INTO demo_log VALUES ('order placed: ' || NEW.item)
Insert on demo_log (actual rows=0.00 loops=1)
Buffers: shared hit=1
-> Result (actual rows=1.00 loops=1)
Nested Statement #4 (level 1):
Query Text: INSERT INTO demo_orders VALUES (2, 'Gadget')
Insert on demo_orders (actual rows=0.00 loops=1)
Buffers: shared hit=1
-> Result (actual rows=1.00 loops=1)
(28 rows)
Key takeaway: Lower statement number = finished earlier.
Triggers finish inside their parent, so they always get lower numbers.
============================================================================
TEST 14: BEGIN/ROLLBACK - Safe Analysis of Data-Modifying Functions
============================================================================
Purpose: Demonstrate the recommended pattern for safely analyzing
functions that modify data without persisting changes.
Pattern:
BEGIN;
EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT my_function();
ROLLBACK;
The function executes (so we get real plans with actual rows),
but ROLLBACK undoes all changes.
psql:comprehensive_nested_statements_test_v3.sql:572: NOTICE: table "safe_orders" does not exist, skipping
DROP TABLE
CREATE TABLE
INSERT 0 2
CREATE FUNCTION
--- Before: ---
id | item | status
----+--------+---------
1 | Widget | pending
2 | Gadget | pending
(2 rows)
--- EXPLAIN inside BEGIN/ROLLBACK: ---
BEGIN
QUERY PLAN
-------------------------------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=11
Nested Plans:
Nested Statement #1 (level 1):
Query Text: UPDATE safe_orders SET status = 'processing' WHERE status = 'pending'
Update on safe_orders (actual rows=0.00 loops=1)
Buffers: shared hit=5
-> Seq Scan on safe_orders (actual rows=2.00 loops=1)
Filter: (status = 'pending'::text)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: INSERT INTO safe_orders VALUES (3, 'Bonus', 'new')
Insert on safe_orders (actual rows=0.00 loops=1)
Buffers: shared hit=1
-> Result (actual rows=1.00 loops=1)
Nested Statement #3 (level 1):
Query Text: DELETE FROM safe_orders WHERE item = 'Gadget'
Delete on safe_orders (actual rows=0.00 loops=1)
Buffers: shared hit=2
-> Seq Scan on safe_orders (actual rows=1.00 loops=1)
Filter: (item = 'Gadget'::text)
Rows Removed by Filter: 2
Buffers: shared hit=1
(27 rows)
ROLLBACK
--- After ROLLBACK (data unchanged): ---
id | item | status
----+--------+---------
1 | Widget | pending
2 | Gadget | pending
(2 rows)
Result: We got full execution plans with actual row counts,
but the data is unchanged after ROLLBACK.
============================================================================
TEST 15: Error During EXPLAIN Does Not Crash Server
============================================================================
Purpose: If EXPLAIN errors (e.g., division by zero), hooks must be
cleaned up so subsequent queries do not crash the backend.
CREATE FUNCTION
psql:comprehensive_nested_statements_test_v3.sql:627: ERROR: division by zero
CONTEXT: SQL statement "SELECT 1/x"
PL/pgSQL function divz_plpgsql(integer) line 4 at SQL statement
After error - next query (should not crash):
post_error_test
-----------------
1
(1 row)
After error - EXPLAIN NESTED_STATEMENTS again:
QUERY PLAN
-----------------------------------
Result (actual rows=1.00 loops=1)
(1 row)
TEST 15: Server survived the error — hooks cleaned up correctly
============================================================================
TEST 16: Nested EXPLAIN Does Not Crash Server
============================================================================
Purpose: A function that internally runs EXPLAIN (NESTED_STATEMENTS)
should not corrupt the outer EXPLAIN state (reentrancy guard).
CREATE FUNCTION
QUERY PLAN
-------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Nested Plans:
Nested Statement #1 (level 1):
Query Text: EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT 1
Result (actual rows=1.00 loops=1)
(7 rows)
TEST 16: Server survived nested EXPLAIN — reentrancy guard works
============================================================================
TEST 17: Memory Context Properly Freed After EXPLAIN
============================================================================
Purpose: The dedicated memory context for nested plans should not
persist after EXPLAIN completes (no memory leak).
QUERY PLAN
-----------------------------------
Result (actual rows=1.00 loops=1)
(1 row)
QUERY PLAN
-----------------------------------
Result (actual rows=1.00 loops=1)
(1 row)
QUERY PLAN
-----------------------------------
Result (actual rows=1.00 loops=1)
(1 row)
Memory contexts named "Nested EXPLAIN plans" (should be 0 rows):
name
------
(0 rows)
TEST 17: 0 rows above = memory context freed after EXPLAIN
============================================================================
TEST 18: Memory Context Does Not Grow Across Repeated Calls
============================================================================
Purpose: Run EXPLAIN NESTED_STATEMENTS 20 times and verify no memory
context persists or accumulates between calls.
CREATE TABLE
INSERT 0 2
CREATE FUNCTION
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=16
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
QUERY PLAN
-----------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM mem_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on mem_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE mem_test SET val = val || 'x' WHERE id = 1
Update on mem_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on mem_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
After 20 runs - "Nested EXPLAIN plans" contexts (should be 0 rows):
name
------
(0 rows)
TEST 18: 0 rows above = no memory accumulation after 20 runs
============================================================================
TEST 19: Stress Test - Function With 50 Nested Statements
============================================================================
Purpose: Verify the feature handles many nested statements without
crashing or corrupting memory.
psql:comprehensive_nested_statements_test_v3.sql:739: NOTICE: table "stress_table" does not exist, skipping
DROP TABLE
CREATE TABLE
INSERT 0 100
CREATE FUNCTION
QUERY PLAN
------------------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=59
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 1
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 2
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 2)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #3 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 3
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 3)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #4 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 4
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 4)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #5 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 5
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 5)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #6 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 6
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 6)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #7 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 7
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 7)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #8 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 8
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 8)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #9 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 9
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 9)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #10 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 10
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 10)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #11 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 11
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 11)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #12 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 12
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 12)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #13 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 13
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 13)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #14 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 14
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 14)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #15 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 15
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 15)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #16 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 16
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 16)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #17 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 17
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 17)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #18 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 18
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 18)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #19 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 19
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 19)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #20 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 20
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 20)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #21 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 21
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 21)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #22 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 22
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 22)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #23 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 23
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 23)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #24 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 24
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 24)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #25 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 25
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 25)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #26 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 26
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 26)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #27 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 27
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 27)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #28 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 28
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 28)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #29 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 29
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 29)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #30 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 30
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 30)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #31 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 31
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 31)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #32 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 32
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 32)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #33 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 33
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 33)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #34 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 34
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 34)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #35 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 35
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 35)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #36 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 36
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 36)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #37 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 37
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 37)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #38 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 38
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 38)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #39 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 39
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 39)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #40 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 40
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 40)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #41 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 41
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 41)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #42 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 42
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 42)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #43 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 43
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 43)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #44 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 44
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 44)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #45 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 45
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 45)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #46 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 46
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 46)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #47 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 47
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 47)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #48 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 48
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 48)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #49 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 49
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 49)
Rows Removed by Filter: 99
Buffers: shared hit=1
Nested Statement #50 (level 1):
Query Text: SELECT COUNT(*) FROM stress_table WHERE id = 50
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on stress_table (actual rows=1.00 loops=1)
Filter: (id = 50)
Rows Removed by Filter: 99
Buffers: shared hit=1
(454 rows)
Server healthy after stress:
server_healthy
----------------
1
(1 row)
No memory leak after stress:
name
------
(0 rows)
TEST 19: 50 nested statements captured, server healthy, no leak
============================================================================
TEST 20: Execution Time Per Nested Statement
============================================================================
Purpose: Each nested statement shows its Execution Time when SUMMARY
is enabled (default with ANALYZE). Uses query_instr->total.
psql:comprehensive_nested_statements_test_v3.sql:821: NOTICE: table "et_test" does not exist, skipping
DROP TABLE
CREATE TABLE
INSERT 0 2
CREATE FUNCTION
Expected: Each nested statement shows "Execution Time: X.XXX ms"
QUERY PLAN
--------------------------------------------------------------------------
Result (actual time=0.200..0.200 rows=1.00 loops=1)
Buffers: shared hit=16
Planning Time: 0.013 ms
Execution Time: 0.206 ms
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM et_test
Aggregate (actual time=0.009..0.009 rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on et_test (actual time=0.006..0.006 rows=2.00 loops=1)
Buffers: shared hit=1
Execution Time: 0.010 ms
Nested Statement #2 (level 1):
Query Text: UPDATE et_test SET val = 'updated' WHERE id = 1
Update on et_test (actual time=0.013..0.013 rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on et_test (actual time=0.003..0.003 rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
Execution Time: 0.014 ms
(24 rows)
============================================================================
TEST 21: Execution Time Hidden with SUMMARY OFF
============================================================================
Purpose: When SUMMARY OFF is specified, nested statements should NOT
show Execution Time (consistent with main query behavior).
Expected: No "Execution Time" lines in nested plans
QUERY PLAN
---------------------------------------------------------------
Result (actual rows=1.00 loops=1)
Buffers: shared hit=4
Nested Plans:
Nested Statement #1 (level 1):
Query Text: SELECT COUNT(*) FROM et_test
Aggregate (actual rows=1.00 loops=1)
Buffers: shared hit=1
-> Seq Scan on et_test (actual rows=2.00 loops=1)
Buffers: shared hit=1
Nested Statement #2 (level 1):
Query Text: UPDATE et_test SET val = 'updated' WHERE id = 1
Update on et_test (actual rows=0.00 loops=1)
Buffers: shared hit=3
-> Seq Scan on et_test (actual rows=1.00 loops=1)
Filter: (id = 1)
Rows Removed by Filter: 1
Buffers: shared hit=1
(20 rows)
DROP FUNCTION
DROP TABLE
============================================================================
TEST 22: Structured Output - JSON Format
============================================================================
Purpose: Nested plans are output as proper structured JSON with
Node Type, Plans array, costs, timing, and execution time.
psql:comprehensive_nested_statements_test_v3.sql:870: NOTICE: table "json_t" does not exist, skipping
DROP TABLE
CREATE TABLE
INSERT 0 2
CREATE FUNCTION
QUERY PLAN
------------------------------------------------------------
[ +
{ +
"Plan": { +
"Node Type": "Result", +
"Parallel Aware": false, +
"Async Capable": false, +
"Startup Cost": 0.00, +
"Total Cost": 0.26, +
"Plan Rows": 1, +
"Plan Width": 4, +
"Actual Startup Time": 0.260, +
"Actual Total Time": 0.260, +
"Actual Rows": 1.00, +
"Actual Loops": 1, +
"Disabled": false, +
"Shared Hit Blocks": 16, +
"Shared Read Blocks": 0, +
"Shared Dirtied Blocks": 0, +
"Shared Written Blocks": 0, +
"Local Hit Blocks": 0, +
"Local Read Blocks": 0, +
"Local Dirtied Blocks": 0, +
"Local Written Blocks": 0, +
"Temp Read Blocks": 0, +
"Temp Written Blocks": 0 +
}, +
"Planning": { +
"Shared Hit Blocks": 0, +
"Shared Read Blocks": 0, +
"Shared Dirtied Blocks": 0, +
"Shared Written Blocks": 0, +
"Local Hit Blocks": 0, +
"Local Read Blocks": 0, +
"Local Dirtied Blocks": 0, +
"Local Written Blocks": 0, +
"Temp Read Blocks": 0, +
"Temp Written Blocks": 0 +
}, +
"Planning Time": 0.015, +
"Triggers": [ +
], +
"Execution Time": 0.266 +
} +
] +
+
Nested Plans: +
+
Nested Statement #1 (level 1): +
Query Text: SELECT COUNT(*) FROM json_t +
[ +
{ +
"Plan": { +
"Node Type": "Aggregate", +
"Strategy": "Plain", +
"Partial Mode": "Simple", +
"Parallel Aware": false, +
"Async Capable": false, +
"Startup Cost": 25.88, +
"Total Cost": 25.89, +
"Plan Rows": 1, +
"Plan Width": 8, +
"Actual Startup Time": 0.010, +
"Actual Total Time": 0.010, +
"Actual Rows": 1.00, +
"Actual Loops": 1, +
"Disabled": false, +
"Shared Hit Blocks": 1, +
"Shared Read Blocks": 0, +
"Shared Dirtied Blocks": 0, +
"Shared Written Blocks": 0, +
"Local Hit Blocks": 0, +
"Local Read Blocks": 0, +
"Local Dirtied Blocks": 0, +
"Local Written Blocks": 0, +
"Temp Read Blocks": 0, +
"Temp Written Blocks": 0, +
"Plans": [ +
{ +
"Node Type": "Seq Scan", +
"Parent Relationship": "Outer", +
"Parallel Aware": false, +
"Async Capable": false, +
"Relation Name": "json_t", +
"Alias": "json_t", +
"Startup Cost": 0.00, +
"Total Cost": 22.70, +
"Plan Rows": 1270, +
"Plan Width": 0, +
"Actual Startup Time": 0.007, +
"Actual Total Time": 0.007, +
"Actual Rows": 2.00, +
"Actual Loops": 1, +
"Disabled": false, +
"Shared Hit Blocks": 1, +
"Shared Read Blocks": 0, +
"Shared Dirtied Blocks": 0, +
"Shared Written Blocks": 0, +
"Local Hit Blocks": 0, +
"Local Read Blocks": 0, +
"Local Dirtied Blocks": 0, +
"Local Written Blocks": 0, +
"Temp Read Blocks": 0, +
"Temp Written Blocks": 0 +
} +
] +
}, +
"Execution Time": 0.011 +
} +
] +
+
Nested Statement #2 (level 1): +
Query Text: UPDATE json_t SET val = 'updated' WHERE id = 1+
[ +
{ +
"Plan": { +
"Node Type": "ModifyTable", +
"Operation": "Update", +
"Parallel Aware": false, +
"Async Capable": false, +
"Relation Name": "json_t", +
"Alias": "json_t", +
"Startup Cost": 0.00, +
"Total Cost": 25.88, +
"Plan Rows": 0, +
"Plan Width": 0, +
"Actual Startup Time": 0.013, +
"Actual Total Time": 0.013, +
"Actual Rows": 0.00, +
"Actual Loops": 1, +
"Disabled": false, +
"Shared Hit Blocks": 3, +
"Shared Read Blocks": 0, +
"Shared Dirtied Blocks": 0, +
"Shared Written Blocks": 0, +
"Local Hit Blocks": 0, +
"Local Read Blocks": 0, +
"Local Dirtied Blocks": 0, +
"Local Written Blocks": 0, +
"Temp Read Blocks": 0, +
"Temp Written Blocks": 0, +
"Plans": [ +
{ +
"Node Type": "Seq Scan", +
"Parent Relationship": "Outer", +
"Parallel Aware": false, +
"Async Capable": false, +
"Relation Name": "json_t", +
"Alias": "json_t", +
"Startup Cost": 0.00, +
"Total Cost": 25.88, +
"Plan Rows": 6, +
"Plan Width": 38, +
"Actual Startup Time": 0.003, +
"Actual Total Time": 0.003, +
"Actual Rows": 1.00, +
"Actual Loops": 1, +
"Disabled": false, +
"Filter": "(id = 1)", +
"Rows Removed by Filter": 1, +
"Shared Hit Blocks": 1, +
"Shared Read Blocks": 0, +
"Shared Dirtied Blocks": 0, +
"Shared Written Blocks": 0, +
"Local Hit Blocks": 0, +
"Local Read Blocks": 0, +
"Local Dirtied Blocks": 0, +
"Local Written Blocks": 0, +
"Temp Read Blocks": 0, +
"Temp Written Blocks": 0 +
} +
] +
}, +
"Execution Time": 0.013 +
} +
] +
(1 row)
DROP FUNCTION
DROP TABLE
============================================================================
TEST 23: Structured Output - XML Format
============================================================================
Purpose: Nested plans are output as proper XML with Node-Type,
Plans elements, costs, timing, and execution time.
psql:comprehensive_nested_statements_test_v3.sql:899: NOTICE: table "xml_t" does not exist, skipping
DROP TABLE
CREATE TABLE
INSERT 0 2
CREATE FUNCTION
QUERY PLAN
--------------------------------------------------------------
<explain xmlns="http://www.postgresql.org/2009/explain"; +
<Query> +
<Plan> +
<Node-Type>Result</Node-Type> +
<Parallel-Aware>false</Parallel-Aware> +
<Async-Capable>false</Async-Capable> +
<Startup-Cost>0.00</Startup-Cost> +
<Total-Cost>0.26</Total-Cost> +
<Plan-Rows>1</Plan-Rows> +
<Plan-Width>4</Plan-Width> +
<Actual-Startup-Time>0.282</Actual-Startup-Time> +
<Actual-Total-Time>0.283</Actual-Total-Time> +
<Actual-Rows>1.00</Actual-Rows> +
<Actual-Loops>1</Actual-Loops> +
<Disabled>false</Disabled> +
<Shared-Hit-Blocks>16</Shared-Hit-Blocks> +
<Shared-Read-Blocks>0</Shared-Read-Blocks> +
<Shared-Dirtied-Blocks>0</Shared-Dirtied-Blocks> +
<Shared-Written-Blocks>0</Shared-Written-Blocks> +
<Local-Hit-Blocks>0</Local-Hit-Blocks> +
<Local-Read-Blocks>0</Local-Read-Blocks> +
<Local-Dirtied-Blocks>0</Local-Dirtied-Blocks> +
<Local-Written-Blocks>0</Local-Written-Blocks> +
<Temp-Read-Blocks>0</Temp-Read-Blocks> +
<Temp-Written-Blocks>0</Temp-Written-Blocks> +
</Plan> +
<Planning> +
<Shared-Hit-Blocks>0</Shared-Hit-Blocks> +
<Shared-Read-Blocks>0</Shared-Read-Blocks> +
<Shared-Dirtied-Blocks>0</Shared-Dirtied-Blocks> +
<Shared-Written-Blocks>0</Shared-Written-Blocks> +
<Local-Hit-Blocks>0</Local-Hit-Blocks> +
<Local-Read-Blocks>0</Local-Read-Blocks> +
<Local-Dirtied-Blocks>0</Local-Dirtied-Blocks> +
<Local-Written-Blocks>0</Local-Written-Blocks> +
<Temp-Read-Blocks>0</Temp-Read-Blocks> +
<Temp-Written-Blocks>0</Temp-Written-Blocks> +
</Planning> +
<Planning-Time>0.010</Planning-Time> +
<Triggers> +
</Triggers> +
<Execution-Time>0.324</Execution-Time> +
</Query> +
</explain> +
+
Nested Plans: +
+
Nested Statement #1 (level 1): +
Query Text: SELECT COUNT(*) FROM xml_t +
<explain xmlns="http://www.postgresql.org/2009/explain"; +
<Query> +
<Plan> +
<Node-Type>Aggregate</Node-Type> +
<Strategy>Plain</Strategy> +
<Partial-Mode>Simple</Partial-Mode> +
<Parallel-Aware>false</Parallel-Aware> +
<Async-Capable>false</Async-Capable> +
<Startup-Cost>25.88</Startup-Cost> +
<Total-Cost>25.89</Total-Cost> +
<Plan-Rows>1</Plan-Rows> +
<Plan-Width>8</Plan-Width> +
<Actual-Startup-Time>0.009</Actual-Startup-Time> +
<Actual-Total-Time>0.010</Actual-Total-Time> +
<Actual-Rows>1.00</Actual-Rows> +
<Actual-Loops>1</Actual-Loops> +
<Disabled>false</Disabled> +
<Shared-Hit-Blocks>1</Shared-Hit-Blocks> +
<Shared-Read-Blocks>0</Shared-Read-Blocks> +
<Shared-Dirtied-Blocks>0</Shared-Dirtied-Blocks> +
<Shared-Written-Blocks>0</Shared-Written-Blocks> +
<Local-Hit-Blocks>0</Local-Hit-Blocks> +
<Local-Read-Blocks>0</Local-Read-Blocks> +
<Local-Dirtied-Blocks>0</Local-Dirtied-Blocks> +
<Local-Written-Blocks>0</Local-Written-Blocks> +
<Temp-Read-Blocks>0</Temp-Read-Blocks> +
<Temp-Written-Blocks>0</Temp-Written-Blocks> +
<Plans> +
<Plan> +
<Node-Type>Seq Scan</Node-Type> +
<Parent-Relationship>Outer</Parent-Relationship> +
<Parallel-Aware>false</Parallel-Aware> +
<Async-Capable>false</Async-Capable> +
<Relation-Name>xml_t</Relation-Name> +
<Alias>xml_t</Alias> +
<Startup-Cost>0.00</Startup-Cost> +
<Total-Cost>22.70</Total-Cost> +
<Plan-Rows>1270</Plan-Rows> +
<Plan-Width>0</Plan-Width> +
<Actual-Startup-Time>0.006</Actual-Startup-Time> +
<Actual-Total-Time>0.007</Actual-Total-Time> +
<Actual-Rows>2.00</Actual-Rows> +
<Actual-Loops>1</Actual-Loops> +
<Disabled>false</Disabled> +
<Shared-Hit-Blocks>1</Shared-Hit-Blocks> +
<Shared-Read-Blocks>0</Shared-Read-Blocks> +
<Shared-Dirtied-Blocks>0</Shared-Dirtied-Blocks> +
<Shared-Written-Blocks>0</Shared-Written-Blocks> +
<Local-Hit-Blocks>0</Local-Hit-Blocks> +
<Local-Read-Blocks>0</Local-Read-Blocks> +
<Local-Dirtied-Blocks>0</Local-Dirtied-Blocks> +
<Local-Written-Blocks>0</Local-Written-Blocks> +
<Temp-Read-Blocks>0</Temp-Read-Blocks> +
<Temp-Written-Blocks>0</Temp-Written-Blocks> +
</Plan> +
</Plans> +
</Plan> +
<Execution-Time>0.010</Execution-Time> +
</Query> +
</explain> +
+
Nested Statement #2 (level 1): +
Query Text: UPDATE xml_t SET val = 'updated' WHERE id = 1 +
<explain xmlns="http://www.postgresql.org/2009/explain"; +
<Query> +
<Plan> +
<Node-Type>ModifyTable</Node-Type> +
<Operation>Update</Operation> +
<Parallel-Aware>false</Parallel-Aware> +
<Async-Capable>false</Async-Capable> +
<Relation-Name>xml_t</Relation-Name> +
<Alias>xml_t</Alias> +
<Startup-Cost>0.00</Startup-Cost> +
<Total-Cost>25.88</Total-Cost> +
<Plan-Rows>0</Plan-Rows> +
<Plan-Width>0</Plan-Width> +
<Actual-Startup-Time>0.013</Actual-Startup-Time> +
<Actual-Total-Time>0.013</Actual-Total-Time> +
<Actual-Rows>0.00</Actual-Rows> +
<Actual-Loops>1</Actual-Loops> +
<Disabled>false</Disabled> +
<Shared-Hit-Blocks>3</Shared-Hit-Blocks> +
<Shared-Read-Blocks>0</Shared-Read-Blocks> +
<Shared-Dirtied-Blocks>0</Shared-Dirtied-Blocks> +
<Shared-Written-Blocks>0</Shared-Written-Blocks> +
<Local-Hit-Blocks>0</Local-Hit-Blocks> +
<Local-Read-Blocks>0</Local-Read-Blocks> +
<Local-Dirtied-Blocks>0</Local-Dirtied-Blocks> +
<Local-Written-Blocks>0</Local-Written-Blocks> +
<Temp-Read-Blocks>0</Temp-Read-Blocks> +
<Temp-Written-Blocks>0</Temp-Written-Blocks> +
<Plans> +
<Plan> +
<Node-Type>Seq Scan</Node-Type> +
<Parent-Relationship>Outer</Parent-Relationship> +
<Parallel-Aware>false</Parallel-Aware> +
<Async-Capable>false</Async-Capable> +
<Relation-Name>xml_t</Relation-Name> +
<Alias>xml_t</Alias> +
<Startup-Cost>0.00</Startup-Cost> +
<Total-Cost>25.88</Total-Cost> +
<Plan-Rows>6</Plan-Rows> +
<Plan-Width>38</Plan-Width> +
<Actual-Startup-Time>0.003</Actual-Startup-Time> +
<Actual-Total-Time>0.004</Actual-Total-Time> +
<Actual-Rows>1.00</Actual-Rows> +
<Actual-Loops>1</Actual-Loops> +
<Disabled>false</Disabled> +
<Filter>(id = 1)</Filter> +
<Rows-Removed-by-Filter>1</Rows-Removed-by-Filter>+
<Shared-Hit-Blocks>1</Shared-Hit-Blocks> +
<Shared-Read-Blocks>0</Shared-Read-Blocks> +
<Shared-Dirtied-Blocks>0</Shared-Dirtied-Blocks> +
<Shared-Written-Blocks>0</Shared-Written-Blocks> +
<Local-Hit-Blocks>0</Local-Hit-Blocks> +
<Local-Read-Blocks>0</Local-Read-Blocks> +
<Local-Dirtied-Blocks>0</Local-Dirtied-Blocks> +
<Local-Written-Blocks>0</Local-Written-Blocks> +
<Temp-Read-Blocks>0</Temp-Read-Blocks> +
<Temp-Written-Blocks>0</Temp-Written-Blocks> +
</Plan> +
</Plans> +
</Plan> +
<Execution-Time>0.013</Execution-Time> +
</Query> +
</explain> +
(1 row)
DROP FUNCTION
DROP TABLE
============================================================================
TEST 24: Structured Output - YAML Format
============================================================================
Purpose: Nested plans are output as proper YAML with Node Type,
Plans list, costs, timing, and execution time.
psql:comprehensive_nested_statements_test_v3.sql:928: NOTICE: table "yaml_t" does not exist, skipping
DROP TABLE
CREATE TABLE
INSERT 0 2
CREATE FUNCTION
QUERY PLAN
------------------------------------------------------------
- Plan: +
Node Type: "Result" +
Parallel Aware: false +
Async Capable: false +
Startup Cost: 0.00 +
Total Cost: 0.26 +
Plan Rows: 1 +
Plan Width: 4 +
Actual Startup Time: 0.179 +
Actual Total Time: 0.179 +
Actual Rows: 1.00 +
Actual Loops: 1 +
Disabled: false +
Shared Hit Blocks: 16 +
Shared Read Blocks: 0 +
Shared Dirtied Blocks: 0 +
Shared Written Blocks: 0 +
Local Hit Blocks: 0 +
Local Read Blocks: 0 +
Local Dirtied Blocks: 0 +
Local Written Blocks: 0 +
Temp Read Blocks: 0 +
Temp Written Blocks: 0 +
Planning: +
Shared Hit Blocks: 0 +
Shared Read Blocks: 0 +
Shared Dirtied Blocks: 0 +
Shared Written Blocks: 0 +
Local Hit Blocks: 0 +
Local Read Blocks: 0 +
Local Dirtied Blocks: 0 +
Local Written Blocks: 0 +
Temp Read Blocks: 0 +
Temp Written Blocks: 0 +
Planning Time: 0.010 +
Triggers: +
Execution Time: 0.185 +
+
Nested Plans: +
+
Nested Statement #1 (level 1): +
Query Text: SELECT COUNT(*) FROM yaml_t +
- Plan: +
Node Type: "Aggregate" +
Strategy: "Plain" +
Partial Mode: "Simple" +
Parallel Aware: false +
Async Capable: false +
Startup Cost: 25.88 +
Total Cost: 25.89 +
Plan Rows: 1 +
Plan Width: 8 +
Actual Startup Time: 0.007 +
Actual Total Time: 0.007 +
Actual Rows: 1.00 +
Actual Loops: 1 +
Disabled: false +
Shared Hit Blocks: 1 +
Shared Read Blocks: 0 +
Shared Dirtied Blocks: 0 +
Shared Written Blocks: 0 +
Local Hit Blocks: 0 +
Local Read Blocks: 0 +
Local Dirtied Blocks: 0 +
Local Written Blocks: 0 +
Temp Read Blocks: 0 +
Temp Written Blocks: 0 +
Plans: +
- Node Type: "Seq Scan" +
Parent Relationship: "Outer" +
Parallel Aware: false +
Async Capable: false +
Relation Name: "yaml_t" +
Alias: "yaml_t" +
Startup Cost: 0.00 +
Total Cost: 22.70 +
Plan Rows: 1270 +
Plan Width: 0 +
Actual Startup Time: 0.005 +
Actual Total Time: 0.005 +
Actual Rows: 2.00 +
Actual Loops: 1 +
Disabled: false +
Shared Hit Blocks: 1 +
Shared Read Blocks: 0 +
Shared Dirtied Blocks: 0 +
Shared Written Blocks: 0 +
Local Hit Blocks: 0 +
Local Read Blocks: 0 +
Local Dirtied Blocks: 0 +
Local Written Blocks: 0 +
Temp Read Blocks: 0 +
Temp Written Blocks: 0 +
Execution Time: 0.008 +
+
Nested Statement #2 (level 1): +
Query Text: UPDATE yaml_t SET val = 'updated' WHERE id = 1+
- Plan: +
Node Type: "ModifyTable" +
Operation: "Update" +
Parallel Aware: false +
Async Capable: false +
Relation Name: "yaml_t" +
Alias: "yaml_t" +
Startup Cost: 0.00 +
Total Cost: 25.88 +
Plan Rows: 0 +
Plan Width: 0 +
Actual Startup Time: 0.011 +
Actual Total Time: 0.011 +
Actual Rows: 0.00 +
Actual Loops: 1 +
Disabled: false +
Shared Hit Blocks: 3 +
Shared Read Blocks: 0 +
Shared Dirtied Blocks: 0 +
Shared Written Blocks: 0 +
Local Hit Blocks: 0 +
Local Read Blocks: 0 +
Local Dirtied Blocks: 0 +
Local Written Blocks: 0 +
Temp Read Blocks: 0 +
Temp Written Blocks: 0 +
Plans: +
- Node Type: "Seq Scan" +
Parent Relationship: "Outer" +
Parallel Aware: false +
Async Capable: false +
Relation Name: "yaml_t" +
Alias: "yaml_t" +
Startup Cost: 0.00 +
Total Cost: 25.88 +
Plan Rows: 6 +
Plan Width: 38 +
Actual Startup Time: 0.003 +
Actual Total Time: 0.004 +
Actual Rows: 1.00 +
Actual Loops: 1 +
Disabled: false +
Filter: "(id = 1)" +
Rows Removed by Filter: 1 +
Shared Hit Blocks: 1 +
Shared Read Blocks: 0 +
Shared Dirtied Blocks: 0 +
Shared Written Blocks: 0 +
Local Hit Blocks: 0 +
Local Read Blocks: 0 +
Local Dirtied Blocks: 0 +
Local Written Blocks: 0 +
Temp Read Blocks: 0 +
Temp Written Blocks: 0 +
Execution Time: 0.011 +
(1 row)
DROP FUNCTION
DROP TABLE
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP TRIGGER
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP TRIGGER
DROP FUNCTION
DROP TABLE
DROP TABLE
DROP TABLE
DROP TABLE
DROP TABLE
DROP TABLE
DROP TABLE
DROP TABLE
DROP TABLE
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP FUNCTION
DROP TABLE
DROP TABLE
============================================================================
Test Suite Complete
============================================================================
KEY FINDING: Nesting levels reflect executor call stack depth.
PERFORM func() / SELECT func() INTO var:
→ Creates new ExecutorRun → deeper nesting level
result := func():
→ ExecEvalFunc (no new ExecutorRun) → SAME nesting level
Tests Covered:
1. Validation (requires ANALYZE)
2. Simple PL/pgSQL (all level 1)
3. PERFORM pattern (creates deeper 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
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. Execution Time hidden with SUMMARY OFF
22. Structured output - JSON format
23. Structured output - XML format
24. Structured output - YAML format
============================================================================
Attachments:
[text/plain] test_output_all_v3.txt (99.0K, 2-test_output_all_v3.txt)
download
[application/octet-stream] v3-0001-Add-NESTED_STATEMENTS-option-to-EXPLAIN.patch (23.6K, 3-v3-0001-Add-NESTED_STATEMENTS-option-to-EXPLAIN.patch)
download | inline diff:
From 29714f041b4270364376a69e17b6cbe99dd79e34 Mon Sep 17 00:00:00 2001
From: Mohamed Ali <[email protected]>
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 <[email protected]>
---
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 [ ( <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> ]
FORMAT { TEXT | XML | JSON | YAML }
</synopsis>
</refsynopsisdiv>
@@ -310,6 +311,39 @@ 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 appear at a deeper level
+ than the triggering statement.
+ </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.
+ 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>FORMAT</literal></term>
<listitem>
@@ -391,6 +425,23 @@ 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 also shows its total execution time when
+ <literal>SUMMARY</literal> is enabled (the default with
+ <literal>ANALYZE</literal>).
+ 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.
+ </para>
</refsect1>
<refsect1>
@@ -575,6 +626,96 @@ 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 (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
+</programlisting>
+
+ This shows the main query plan followed by the plans for each SQL
+ statement executed inside <function>my_function()</function>. The
+ nesting level indicates the executor call stack depth.
+ </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",
+ "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
+ }
+]
+</programlisting>
+
+ 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.
+ </para>
</refsect1>
<refsect1>
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("<unknown>");
+ 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)
[application/octet-stream] comprehensive_nested_statements_test_v3.sql (41.6K, 4-comprehensive_nested_statements_test_v3.sql)
download
reply
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: [email protected]
Cc: [email protected], [email protected], [email protected]
Subject: Re: [PATCH] Add NESTED_STATEMENTS option to EXPLAIN
In-Reply-To: <CAGnOmWoyrffJeJ9uz6wkB0arO4BPDMRK-YemicT1Prp4umtrJA@mail.gmail.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox