Thread
-
[PATCH] Add NESTED_STATEMENTS option to EXPLAIN
Mohamed ALi <moali.pg@gmail.com> — 2026-05-16T06:48:58Z
Hi hackers, I'd like to propose adding NESTED_STATEMENTS as a core EXPLAIN option that displays execution plans for SQL statements executed within called functions and procedures. Motivation ---------- Currently, to see execution plans for nested statements inside PL/pgSQL functions, users must: 1. Add auto_explain to shared_preload_libraries 2. Restart the database 3. Set session-level GUCs: SET client_min_messages TO log; SET auto_explain.log_nested_statements = ON; SET auto_explain.log_min_duration = 0; SELECT my_function(); 4. Check server logs for the output With this patch, users can simply run: EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT my_function(); Note: Requires ANALYZE (validated with clear error message) and see the plans for all nested statements directly in the EXPLAIN output, with no extension loading or configuration required. How It Works ------------ The feature temporarily installs executor hooks (ExecutorStart, Run, Finish, End) during the EXPLAIN execution to track query nesting depth and capture plans for nested statements. After the main query plan is displayed, nested plans are appended with: - Sequential statement number - Nesting level (executor call stack depth) - Query text - Complete execution plan (inheriting VERBOSE, BUFFERS, etc. options) Example: -- Setup CREATE TABLE products (id INT, name TEXT, price NUMERIC, category TEXT); INSERT INTO products VALUES (1, 'Laptop', 999, 'Electronics'), (2, 'Phone', 699, 'Electronics'), (3, 'Book', 19, 'Books'); CREATE FUNCTION update_products() RETURNS void AS $$ DECLARE cnt INTEGER; BEGIN SELECT COUNT(*) INTO cnt FROM products WHERE category = 'Electronics'; UPDATE products SET price = price * 1.10 WHERE category = 'Electronics'; INSERT INTO products (name, price, category) VALUES ('Keyboard', 79, 'Electronics'); DELETE FROM products WHERE price < 5; END; $$ LANGUAGE plpgsql; -- Run EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT update_products(); 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 WHERE category = 'Electronics' 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=2.00 loops=1) Filter: (category = 'Electronics'::text) Rows Removed by Filter: 1 Buffers: shared hit=1 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=2.00 loops=1) Filter: (category = 'Electronics'::text) Rows Removed by Filter: 1 Buffers: shared hit=1 Nested Statement #3 (level 1): Query Text: INSERT INTO products (name, price, category) VALUES ('Keyboard', 79, 'Electronics') Insert on products (actual rows=0.00 loops=1) Buffers: shared hit=1 -> Result (actual rows=1.00 loops=1) Nested Statement #4 (level 1): Query Text: DELETE FROM products WHERE price < 5 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 < '5'::numeric) Rows Removed by Filter: 4 Buffers: shared hit=1 Nesting Level Semantics ----------------------- The nesting level reflects the executor call stack depth. Here's a visual representation of the level1_func example above: EXPLAIN SELECT level1_func(); ← Level 0 (top-level, not shown) │ └─→ level1_func() executes │ ├─→ PERFORM COUNT(*) FROM products → Level 1, Statement #1 │ ├─→ PERFORM level2_func() → creates new executor │ │ │ └─→ level2_func() executes │ │ │ ├─→ PERFORM COUNT(*) WHERE id = 1 → Level 2, Statement #2 │ │ │ └─→ PERFORM level3_func() → creates new executor │ │ │ └─→ level3_func() executes │ │ │ └─→ PERFORM COUNT(*) WHERE category = 'Books' │ → Level 3, Statement #3 │ │ (level3_func returns) → Level 2, Statement #4 │ (level2_func returns) → Level 1, Statement #5 │ └─→ (done) The level number = how many PERFORM/SELECT calls are on the stack. The nesting level reflects the executor call stack depth: - Statements in a function called via PERFORM or SELECT INTO run at a deeper level than the caller. - Statements in a function called via expression assignment (result := func()) run at the same level as the caller, because no new executor call is created. - Trigger-fired statements appear at a deeper level than the triggering statement. - SQL functions create true nesting since they execute during the parent query. This is consistent with how auto_explain tracks nesting internally. Example showing multiple nesting levels: CREATE FUNCTION level3_func() RETURNS void AS $$ BEGIN PERFORM COUNT(*) FROM products WHERE category = 'Books'; END; $$ LANGUAGE plpgsql; CREATE FUNCTION level2_func() RETURNS void AS $$ BEGIN PERFORM COUNT(*) FROM products WHERE id = 1; PERFORM level3_func(); END; $$ LANGUAGE plpgsql; CREATE FUNCTION level1_func() RETURNS void AS $$ BEGIN PERFORM COUNT(*) FROM products; PERFORM level2_func(); END; $$ LANGUAGE plpgsql; EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT level1_func(); QUERY PLAN --------------------------------------------------------------- Result (actual time=1.701..1.702 rows=1.00 loops=1) Buffers: shared hit=35 Planning Time: 0.036 ms Execution Time: 3.820 ms Nested Plans: Nested Statement #1 (level 1): Query Text: SELECT COUNT(*) FROM products Aggregate (actual time=0.011..0.012 rows=1.00 loops=1) Buffers: shared hit=1 -> Seq Scan on products (actual time=0.008..0.009 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 time=0.006..0.006 rows=1.00 loops=1) Buffers: shared hit=1 -> Seq Scan on products (actual time=0.005..0.005 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 time=0.003..0.003 rows=1.00 loops=1) Buffers: shared hit=1 -> Seq Scan on products (actual time=0.002..0.002 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 level3_func() Result (actual time=0.049..0.049 rows=1.00 loops=1) Buffers: shared hit=1 Nested Statement #5 (level 1): Query Text: SELECT level2_func() Result (actual time=0.217..0.217 rows=1.00 loops=1) Buffers: shared hit=28 Each PERFORM creates a new executor level, so the nesting depth increases with each function call in the chain. Testing ------- I've also included a comprehensive test script (comprehensive_nested_statements_test.sql) that covers 14 test cases: 1. Validation (NESTED_STATEMENTS requires ANALYZE) 2. Simple PL/pgSQL function (all statements at level 1) 3. PERFORM pattern (creates deeper nesting levels) 4. Expression assignment (stays at same level) 5. Side-by-side comparison of PERFORM vs expression assignment 6. SQL function nesting (true SQL nesting, levels 2-3) 7. Three-level PL/pgSQL chain with PERFORM 8. Recursive function (increasing levels) 9. Exception handling blocks 10. No nested statements (plain query, no Nested Plans section) 11. Trigger-fired nested statements 12. Combined with VERBOSE and BUFFERS options 13. Statement numbering = completion order (triggers demo) 14. BEGIN/ROLLBACK safety pattern To run the test script and save output: psql -f comprehensive_nested_statements_test.sql > test_output_all.txt 2>&1 The test output file (test_output_all.txt) shows the full EXPLAIN output for each test case with explanations of expected behavior. Structured output formats (JSON, XML, YAML) have been tested and work correctly. In structured formats, the nested plans appear as a text string within the Plan field rather than as structured plan nodes. This could be improved in a future version. -- Mohamed Ali AWS RDS -
Re: [PATCH] Add NESTED_STATEMENTS option to EXPLAIN
Zsolt Parragi <zsolt.parragi@percona.com> — 2026-05-16T11:15:34Z
Hello! With some initial testing I was able to find 2 server crashes with the patch. 1: error during explain CREATE OR REPLACE FUNCTION divz_plpgsql(x int) RETURNS int LANGUAGE plpgsql AS $$ DECLARE r int; BEGIN SELECT 1/x INTO r; RETURN r; END; $$; -- error during explain EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT divz_plpgsql(0); -- run another explain EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT 1; -- any next query crashes the server SELECT 1; 2: any nested explain CREATE FUNCTION f() RETURNS void LANGUAGE plpgsql AS $$ DECLARE r record; BEGIN FOR r IN EXECUTE 'EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT 1' LOOP NULL; END LOOP; END; $$; EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT f(); + /* + * Switch to TopMemoryContext so the captured plan text survives + * until we print it. + */ + oldcxt = MemoryContextSwitchTo(TopMemoryContext); ... + ExplainBeginOutput(nes); + ExplainPrintPlan(nes, queryDesc); + ExplainEndOutput(nes); ... + plan_info->query_text = queryDesc->sourceText ? + pstrdup(queryDesc->sourceText) : pstrdup("<unknown>"); When is queryDesc freed? This seems like a memory leak. -
Re: [PATCH] Add NESTED_STATEMENTS option to EXPLAIN
Mohamed ALi <moali.pg@gmail.com> — 2026-05-16T14:52:48Z
Hi Zsolt, Thanks for testing! I've identified the root causes and am working on v2 with the fixes. Will share soon. -- Mohamed Ali On Sat, May 16, 2026 at 4:15 AM Zsolt Parragi <zsolt.parragi@percona.com> wrote: > > Hello! > > With some initial testing I was able to find 2 server crashes with the patch. > > 1: error during explain > > CREATE OR REPLACE FUNCTION divz_plpgsql(x int) RETURNS int LANGUAGE > plpgsql AS $$ > DECLARE r int; > BEGIN > SELECT 1/x INTO r; > RETURN r; > END; > $$; > -- error during explain > EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT divz_plpgsql(0); > -- run another explain > EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT 1; > -- any next query crashes the server > SELECT 1; > > 2: any nested explain > > CREATE FUNCTION f() RETURNS void LANGUAGE plpgsql AS $$ > DECLARE r record; > BEGIN > FOR r IN EXECUTE 'EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT 1' > LOOP NULL; END LOOP; > END; > $$; > > EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT f(); > > > + /* > + * Switch to TopMemoryContext so the captured plan text survives > + * until we print it. > + */ > + oldcxt = MemoryContextSwitchTo(TopMemoryContext); > ... > + ExplainBeginOutput(nes); > + ExplainPrintPlan(nes, queryDesc); > + ExplainEndOutput(nes); > ... > + plan_info->query_text = queryDesc->sourceText ? > + pstrdup(queryDesc->sourceText) : pstrdup("<unknown>"); > > When is queryDesc freed? This seems like a memory leak. > > -
Re: [PATCH] Add NESTED_STATEMENTS option to EXPLAIN
Mohamed ALi <moali.pg@gmail.com> — 2026-05-17T16:45:40Z
Hi Zsolt, Attached is v2 of the patch which fixes all three issues: 1. Error during EXPLAIN (e.g., division by zero): - Root cause: hooks were not removed on the error path. - Fix: wrapped EXPLAIN execution in PG_TRY/PG_FINALLY to guarantee hook removal and cleanup regardless of errors. 2. Nested EXPLAIN crash: - Root cause: static globals overwritten by the inner EXPLAIN. - Fix: added a reentrancy guard — if nested tracking is already active, the inner EXPLAIN skips hook installation entirely. 3. Memory leak (TopMemoryContext): - Root cause: allocating captured plans in TopMemoryContext with no cleanup on error. - Fix: replaced TopMemoryContext with a dedicated memory context ("Nested EXPLAIN plans") that is created at the start and deleted in PG_FINALLY — freeing everything at once on both success and error paths. The v2 patch passes the regression test suite (245 subtests, 0 failures) and a comprehensive 19-test script covering the original functionality plus the three bug scenarios, memory leak verification, and a stress test with 50 nested statements. Attachments: 1- v2-0001-Add-NESTED_STATEMENTS-option-to-EXPLAIN.patch 2- comprehensive_nested_statements_test_v2.sql 3- test_output_all_v2.txt Mohamed Ali AWS RDS -
Re: [PATCH] Add NESTED_STATEMENTS option to EXPLAIN
Mohamed ALi <moali.pg@gmail.com> — 2026-05-21T20:51:58Z
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
-
Re: [PATCH] Add NESTED_STATEMENTS option to EXPLAIN
Mohamed ALi <moali.pg@gmail.com> — 2026-05-26T18:32:26Z
Subject: [PATCH v4] Add NESTED_STATEMENTS option to EXPLAIN Hi, Attached is v4 of the patch adding NESTED_STATEMENTS as a core EXPLAIN option. This version adds significant new features on top of v3 Changes since v3: - Added SHOW_NESTED integer option to limit displayed plans - Added Nested Statements Summary (total, max depth, timing, slowest) - Added per-statement execution time percentage (level-1 only, %.1f) - Added trigger detection via GetMyTriggerDepth() from trigger.c: both BEFORE and AFTER triggers annotated with "(trigger)", parent statements show "Trigger X: time=Y calls=Z" lines, separate Total Trigger Time in summary (% of nested time) - Total Nested Time and Total Trigger Time sum only level-1 statements (deeper levels' time is already included in their level-1 parent) - Works directly on DML with triggers and inside functions (reveals trigger activity unreachable by built-in reporting) - Query Identifier shown with VERBOSE (correlates with pg_stat_statements) - Updated documentation with all new features and examples == Feature Overview == 1. SHOW_NESTED Option --------------------- Controls how many nested plans are displayed. All statements are still captured internally for the summary, but only the first N plans appear in the output. Use SHOW_NESTED 0 for summary-only mode. Note: This is purely a display control, it does not limit execution or capture depth. PostgreSQL already has max_stack_depth to prevent runaway recursion at the execution level. SHOW_NESTED addresses a different problem: managing output size when a function legitimately executes many statements. EXPLAIN (ANALYZE, NESTED_STATEMENTS, SHOW_NESTED 2) SELECT my_func(); Nested Plans (showing 2 of 5): Nested Statement #1 (level 1): Query Text: SELECT COUNT(*) FROM t WHERE id = 1 ... Execution Time: 0.011 ms (36.0%) Nested Statement #2 (level 1): Query Text: SELECT COUNT(*) FROM t WHERE id = 2 ... Execution Time: 0.010 ms (33.0%) Nested Statements Summary: Total: 5 statements, max depth 1 Total Execution Time: 0.353 ms Total Nested Time: 0.030 ms (9.0% of total time) Slowest Statement: #1 (0.011 ms, 36.0%) SHOW_NESTED 0 shows only the summary without any individual plans. Requires NESTED_STATEMENTS to be enabled. 2. Nested Statements Summary ---------------------------- Thanks to Ryan Booz and Lukas Fittl for the discussion at PGCon DEV 2026 which inspired the Nested Statements Summary feature. A summary section appears after the nested plans showing key metrics: Nested Statements Summary: Total: 5 statements (3 direct, 2 trigger-fired), max depth 3 Total Execution Time: 1.300 ms Total Nested Time: 1.001 ms (77.0% of total time) Total Trigger Time: 0.125 ms (12.5% of nested time) Slowest Statement: #2 (0.800 ms, 79.9%) - Total Execution Time: the main query's wall-clock execution time (same value as "Execution Time" in the main plan) - Total Nested Time: sum of level-1 direct (non-trigger) statement times, with percentage of total execution time - Total Trigger Time: sum of level-1 trigger-fired statement times, shown as percentage of nested time (only appears when triggers fire) - Slowest Statement: identifies the bottleneck immediately - Controlled by the SUMMARY option (on by default with ANALYZE) The percentage answers: "What fraction of total execution time is accounted for by the captured SQL statements?" Example A — High % (SQL-heavy): Total Execution Time: 50.000 ms Total Nested Time: 48.500 ms (97.0% of total time) → Almost all time is in SQL. Use per-statement % to find the slow query (e.g., a missing index on a WHERE clause). Example B — Low % (overhead-heavy): Total Execution Time: 10.000 ms Total Nested Time: 0.500 ms (5.0% of total time) → SQL finishes in 0.5ms but the function takes 10ms total. The gap (9.5ms) is PL/pgSQL interpreter overhead: loops, conditionals, variable assignments, SPI context switches, exception block setup. Consider rewriting as a single SQL statement or reducing loop iterations. 3. Per-Statement Execution Time with Percentage ------------------------------------------------ Each level-1 nested statement shows its execution time and what fraction of the total nested time it represents. Deeper-level statements show only absolute time (their time is already included in their level-1 parent): Nested Statement #1 (level 1): Query Text: SELECT COUNT(*) FROM products Aggregate (actual time=0.200..0.201 rows=1.00 loops=1) -> Seq Scan on products (...) Execution Time: 0.201 ms (20.1%) Nested Statement #2 (level 1): Query Text: UPDATE products SET price = price * 1.10 WHERE ... Update on products (actual time=0.800..0.800 rows=0.00 loops=1) -> Seq Scan on products (...) Execution Time: 0.800 ms (79.9%) Percentages use one decimal place to avoid misleading rounding (e.g., 99.8% instead of 100% when there are multiple statements). Level-1 percentages always sum to ≤100%. 4. Trigger Detection -------------------- Both BEFORE and AFTER trigger-fired statements are automatically detected and annotated. Detection uses GetMyTriggerDepth() a new C-callable getter for the existing MyTriggerDepth variable in trigger.c (the same variable backing pg_trigger_depth() SQL function). EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT process_order(1); Nested Statement #1 (level 2, trigger): Query Text: INSERT INTO audit_log (order_id, action) VALUES (...) Insert on audit_log (actual time=0.522..0.522 rows=0.00 loops=1) Execution Time: 0.522 ms Nested Statement #2 (level 1): Query Text: INSERT INTO orders VALUES (p_id, 99.99, 'new') Insert on orders (actual time=0.842..0.842 rows=0.00 loops=1) -> Result (actual time=0.001..0.001 rows=1.00 loops=1) Trigger order_audit_trigger: time=0.522 calls=1 Execution Time: 1.520 ms (96.2%) Nested Statements Summary: Total: 4 statements (2 direct, 2 trigger-fired), max depth 2 Total Execution Time: 1.784 ms Total Nested Time: 1.580 ms (88.6% of total time) Total Trigger Time: 0.527 ms (33.3% of nested time) Slowest Statement: #2 (1.520 ms, 96.2%) Key design decisions: - Detection uses GetMyTriggerDepth() > 0, which catches both BEFORE and AFTER triggers (MyTriggerDepth is incremented in ExecCallTriggerFunc before the trigger function runs, regardless of trigger timing) - pg_trigger_depth() SQL function refactored to use the same getter (zero behavior change, just shares the accessor) - Trigger statements show no percentage (their time is already included in the parent statement's time, they're not additive) - Total Trigger Time is shown as % of nested time, telling users how much of their SQL time is actually trigger overhead - Summary shows "(N direct, M trigger-fired)" breakdown - When no triggers are involved, trigger-related output is suppressed - Nested statements that fire triggers show "Trigger X: time=Y calls=Z" lines in their plan output (matching top-level EXPLAIN behavior) - This also reveals trigger activity inside functions, which PostgreSQL's built-in "Trigger X: time=Y calls=Z" reporting cannot reach (it only reports triggers on the top-level statement) 5. Direct DML Trigger Visibility --------------------------------- NESTED_STATEMENTS works directly on DML statements that fire triggers, without needing to wrap anything in a function: EXPLAIN (ANALYZE, NESTED_STATEMENTS) UPDATE emp SET salary = salary * 1.10 WHERE salary < 65000; Nested Statement #1 (level 2, trigger): Query Text: INSERT INTO notifications VALUES (...) ... Execution Time: 0.415 ms Nested Statement #2 (level 1, trigger): Query Text: INSERT INTO emp_audit VALUES (OLD.id, OLD.salary, NEW.salary) ... Execution Time: 1.221 ms Nested Statements Summary: Total: 4 statements (0 direct, 4 trigger-fired), max depth 2 Total Execution Time: 5.440 ms Total Trigger Time: 1.692 ms Slowest Statement: #2 (1.221 ms) This reveals cascading trigger chains: the UPDATE fires an audit trigger (level 1), which inserts into emp_audit, which fires a notification trigger (level 2). Users can immediately see why their simple UPDATE is slow. 6. Query Identifier Integration (pg_stat_statements) ----------------------------------------------------- When VERBOSE is enabled and compute_query_id is active, each nested statement shows its Query Identifier. Repeated queries (same SQL with different parameters) share the same identifier, allowing users to correlate nested plans with pg_stat_statements entries: SET compute_query_id = on; EXPLAIN (ANALYZE, NESTED_STATEMENTS, VERBOSE, COSTS OFF) SELECT process_orders(); Nested Statement #1 (level 1): Query Text: SELECT COUNT(*) FROM orders Aggregate (...) Query Identifier: 213668903401070912 Execution Time: 0.012 ms (0.2%) Nested Statement #3 (level 2): Query Text: UPDATE orders SET total = total * (1 - p_pct/100) WHERE id = p_id Update on orders (...) Query Identifier: -4236462531438235649 Trigger audit_trig: time=1.110 calls=1 Execution Time: 1.172 ms (15.2%) Users can then query: SELECT * FROM pg_stat_statements WHERE queryid = -4236462531438235649; This requires no additional code — it works because ExplainPrintPlan already shows Query Identifier when VERBOSE is enabled, and SPI computes queryIds for nested statements when compute_query_id is on. == Implementation Notes == - Trigger detection uses GetMyTriggerDepth() a new getter function added to trigger.c that exposes the existing MyTriggerDepth variable. pg_trigger_depth() SQL function refactored to use the same getter. Detects both BEFORE and AFTER triggers with a single check. - Each nested statement's plan includes ExplainPrintTriggers() output, showing which triggers it fired (matches top-level EXPLAIN behavior) - Total Nested Time only sums level-1 direct (non-trigger) statements; deeper levels show absolute time but are not added to the total (their time is already included in their level-1 parent's time) - Total Trigger Time similarly sums only level-1 trigger statements to avoid overcounting with cascading triggers - SHOW_NESTED controls display only; all statements are still captured for accurate summary statistics regardless of the display limit - The show_nested field defaults to -1 (show all); 0 means summary only - Structured formats (JSON/XML/YAML) include Execution Time as a typed numeric field inside each nested plan's structure - This feature reveals trigger activity inside functions that PostgreSQL's built-in trigger reporting ("Trigger X: time=Y calls=Z") cannot reach == Test Suite == The patch includes a comprehensive test script with 41 test cases covering all features, edge cases, and error handling. The full output is attached so reviewers can see actual behavior without needing to apply the patch, and to help identify any test cases I may have missed: comprehensive_nested_statements_test_v4.sql (test script) test_output_all_v4.txt (full output) Test cases: 1. Validation (NESTED_STATEMENTS requires ANALYZE) 2. Simple PL/pgSQL function (all level 1) 3. PERFORM pattern (creates deeper nesting levels) 4. Expression assignment (stays at same level) 5. Side-by-side comparison of both patterns 6. SQL function nesting (true SQL nesting) 7. Three-level chain with PERFORM 8. Recursive function (increasing levels) 9. Exception handling blocks 10. No nested statements (plain query) 11. Trigger-fired nested statements (with detection) 12. Combined with VERBOSE and BUFFERS 13. Statement numbering = completion order (triggers demo) 14. BEGIN/ROLLBACK safety pattern 15. Error during EXPLAIN does not crash (Bug 1 fix) 16. Nested EXPLAIN does not crash (Bug 2 fix) 17. Memory context cleanup (Bug 3 fix) 18. Memory context does not grow across repeated calls 19. Stress test - 50 nested statements 20. Execution Time per nested statement (SUMMARY default) 21. SUMMARY OFF hides timing, percentages, and summary section 22. Structured output - JSON format 23. Structured output - XML format 24. Structured output - YAML format 25. SHOW_NESTED - limit displayed plans 26. SHOW_NESTED 0 - summary only 27. SHOW_NESTED validation (requires NESTED_STATEMENTS) 28. Nested Statements Summary with percentages 29. Statement timeout - hooks cleaned up 30. Dynamic SQL - query text captured correctly 31. Infinite recursion - graceful error (max_stack_depth protects execution; hooks cleaned up via PG_FINALLY, server continues) 32. auto_explain compatibility 33. Deep nesting (20 levels) 34. All EXPLAIN options combined with SHOW_NESTED 35. Performance - zero overhead when disabled 36. Interpreting Total Nested Time percentage 37. Multiple triggers on separate tables 38. Direct DML with triggers (BEFORE + AFTER, cascading, rejection) 39. BEFORE and AFTER triggers in function context 40. Query Identifier integration (pg_stat_statements) 41. Level-1 only counting (no double-counting with deep nesting) == Open Questions == 1. Should the per-statement percentage be available in JSON format as a separate "Execution Time Percentage" field? Currently it's only shown in TEXT format and the summary. 2. Should there be a MAX_DEPTH option to limit capture by nesting level (complementing SHOW_NESTED which limits by count)? Mohamed Ali AWS RDS -
Re: [PATCH] Add NESTED_STATEMENTS option to EXPLAIN
Zsolt Parragi <zsolt.parragi@percona.com> — 2026-05-28T22:08:37Z
+<programlisting> +EXPLAIN (ANALYZE, NESTED_STATEMENTS, FORMAT JSON) SELECT my_function(); and + Each nested plan is a valid JSON document that can be parsed independently. + The metadata headers (statement number, nesting level, query text) and the + summary appear as plain text between the JSON blocks. The + <literal>Execution Time</literal> field is included inside each nested + plan's JSON structure when <literal>SUMMARY</literal> is enabled. + Percentages are shown only in the text-format summary, not inside the + structured plan objects.0 Are you sure this is correct? My expectation would be for FORMAT JSON to output a valid, usable JSON document. E.g.: bin/psql -X -t -A -d db -c "EXPLAIN (FORMAT JSON) SELECT ..." > file.json writes a valid json file which I can then parse with any json parser. If I do the same with NESTED_STATEMENTS, I get an invalid json. It's not only a concatenation of multiple json documents, but also includes additional completely non-json text in it. It seems difficult to parse/use. Same goes for XML/YAML. + if (!is_trigger && nested_exec_level == 1 && + stmt_time > nested_slowest_time) + { + nested_slowest_time = stmt_time; + nested_slowest_num = nested_total_count; + } Why is the slowest statement check limited to nesting level 1? For example, see the following test case where it doesn't display any slowest statement: CREATE TABLE big(n int); INSERT INTO big SELECT g FROM generate_series(1, 200000) g; CREATE TABLE t_a(id int primary key); CREATE TABLE t_log(id int); INSERT INTO t_a VALUES (1); CREATE OR REPLACE FUNCTION slow_trig() RETURNS trigger LANGUAGE plpgsql AS $$ DECLARE r bigint; BEGIN SELECT count(*) FROM big a, generate_series(1, 40) b INTO r; INSERT INTO t_log VALUES (NEW.id); RETURN NEW; END; $$; CREATE TRIGGER slow_trigger AFTER UPDATE ON t_a FOR EACH ROW EXECUTE FUNCTION slow_trig(); EXPLAIN (ANALYZE, NESTED_STATEMENTS, COSTS OFF, TIMING ON) UPDATE t_a SET id = id WHERE id = 1; Trigger time calculation also doesn't work for multiple nesting levels, see: CREATE TABLE t(i int); CREATE FUNCTION trg() RETURNS trigger LANGUAGE plpgsql AS $$ BEGIN PERFORM pg_sleep(0.05); RETURN NEW; END $$; CREATE TRIGGER trg BEFORE INSERT ON t FOR EACH ROW EXECUTE FUNCTION trg(); CREATE FUNCTION f() RETURNS void LANGUAGE plpgsql AS $$ BEGIN INSERT INTO t VALUES(1); END $$; EXPLAIN (ANALYZE, NESTED_STATEMENTS, COSTS OFF, TIMING OFF, BUFFERS OFF) SELECT f(); And staying with the topic of triggers, are you sure that all statements that are executed within triggers should get a trigger label? Wouldn't it be better to track only directly trigger-executed statements? + <literal>SUMMARY</literal> is enabled. Level-1 statements (those + directly inside the called function) also show a percentage of total + nested time. Deeper-level statements show only absolute time because + their time is already included in their level-1 parent's reported time. + Nested statements are numbered in completion order. Wouldn't start-time ordering be better rather than completion? Right now, it includes children before the caller, which could look confusing. With a multi level difference between statement it is clearer, but if a level 2 statement follows a level 1 statement, my first thought that the level 1 statement called the level 2. But it didn't, the next level 1 did.