From b95e3addb6a0deb3fd9474df7231d45f1d83a75e Mon Sep 17 00:00:00 2001 From: Mohamed Ali Date: Fri, 15 May 2026 15:10:31 -0700 Subject: [PATCH v4] Add NESTED_STATEMENTS option to EXPLAIN Add a new EXPLAIN option, NESTED_STATEMENTS, that captures and displays execution plans for SQL statements executed within called functions, procedures, and triggers. This provides similar functionality to auto_explain's log_nested_statements parameter but as a core EXPLAIN option requiring no extension or GUC configuration. Features: - NESTED_STATEMENTS boolean option (requires ANALYZE) - Installs executor hooks (Start/Run/Finish/End) to track nesting - Captures plan text, query text, nesting level, and execution time - Displays nested plans after the main query plan - SHOW_NESTED integer option to limit displayed plans (0 = summary only) - Nested Statements Summary with total count, max depth, and timing - Per-statement execution time with percentage (level-1 statements only; deeper levels show absolute time since their time is already included in their level-1 parent's inclusive time) - Total Nested Time sums only level-1 statement times to avoid double-counting when multi-level nesting is present - Trigger detection via GetMyTriggerDepth(): detects both BEFORE and AFTER triggers, annotates with (trigger) in output - Separate Total Trigger Time tracking (level-1 triggers only, shown as % of nested time) - Works directly on DML with triggers (no function wrapper needed) - Reveals trigger activity inside functions (unreachable by built-in trigger reporting which only covers the top-level statement) - Inherits parent EXPLAIN options (VERBOSE, COSTS, BUFFERS, WAL, FORMAT) - Structured output for JSON/XML/YAML formats - Error-safe: PG_TRY/PG_FINALLY ensures hook cleanup on errors - Reentrancy guard: nested EXPLAIN(NESTED_STATEMENTS) does not crash - Dedicated memory context: no leaks, freed in PG_FINALLY trigger.c changes: - Add GetMyTriggerDepth() getter function for MyTriggerDepth - Refactor pg_trigger_depth() SQL function to use the getter Documentation updated with parameter descriptions, notes on trigger detection, level-1 timing semantics, and examples in TEXT, SHOW_NESTED, and JSON formats. --- doc/src/sgml/ref/explain.sgml | 338 +++++++++++++++ src/backend/commands/explain.c | 611 +++++++++++++++++++++++++-- src/backend/commands/explain_state.c | 25 ++ src/backend/commands/trigger.c | 18 +- src/include/commands/explain_state.h | 2 + src/include/commands/trigger.h | 2 + 6 files changed, 961 insertions(+), 35 deletions(-) diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml index e95e19081e1..1482426fe65 100644 --- a/doc/src/sgml/ref/explain.sgml +++ b/doc/src/sgml/ref/explain.sgml @@ -47,6 +47,8 @@ EXPLAIN [ ( option [, ...] ) ] boolean ] MEMORY [ boolean ] IO [ boolean ] + NESTED_STATEMENTS [ boolean ] + SHOW_NESTED integer FORMAT { TEXT | XML | JSON | YAML } @@ -310,6 +312,70 @@ ROLLBACK; + + NESTED_STATEMENTS + + + 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. + + + 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 PERFORM or + SELECT ... INTO run at a deeper level than the + caller, while statements in a function called via expression assignment + (e.g., result := func()) run at the same level as + the caller. Statements fired by triggers (both + BEFORE and AFTER) are + automatically detected and annotated with + (trigger) in the output. Nested statements that + fire triggers also show trigger timing information in their plan. + When VERBOSE is enabled, each nested statement + includes its Query Identifier for correlation + with pg_stat_statements. + + + This option provides similar functionality to + 's + auto_explain.log_nested_statements parameter, but + without requiring the extension to be loaded or any GUC configuration. + It also works directly on DML statements + (INSERT, UPDATE, + DELETE) that fire triggers, revealing the + execution plans of trigger-fired statements without needing to + wrap the query in a function. + A summary section is included after the nested plans showing + total statement count, execution time breakdown, and the slowest + statement (controlled by the SUMMARY option). + This parameter may only be used when ANALYZE is also + enabled. It defaults to FALSE. + + + + + + SHOW_NESTED + + + Limit the number of nested statement plans displayed in the output. + When specified, only the first N nested + plans are shown, but all statements are still captured internally + for the summary statistics. Use SHOW_NESTED 0 + to display only the summary without any individual plans. + This is useful for complex functions with many nested statements + where the full output would be too large. + This parameter may only be used when NESTED_STATEMENTS + is also enabled. When not specified, all nested plans are displayed. + + + + FORMAT @@ -391,6 +457,55 @@ ROLLBACK; execution, and on machines that have relatively slow operating system calls for obtaining the time of day. + + + When NESTED_STATEMENTS is enabled, the options + VERBOSE, COSTS, + BUFFERS, WAL, + TIMING, and FORMAT + are inherited by the nested statement plans. + Each nested statement shows its execution time when + SUMMARY is enabled. Level-1 statements (those + directly inside the called function) also show a percentage of total + nested time. Deeper-level statements show only absolute time because + their time is already included in their level-1 parent's reported time. + Nested statements are numbered in completion order. + When using structured output formats (JSON, XML, YAML), each nested + plan is emitted as a structured object matching the main plan format. + + + + A summary section controlled by SUMMARY shows: + total statement count, maximum nesting depth, total nested execution + time (as percentage of main execution time), total trigger time + (as percentage of nested time), and the slowest statement. + Total nested time sums only level-1 statement times to avoid + double-counting when deeper levels are present (since level-1 + times already include their children's execution time). + Use SHOW_NESTED 0 to display only the summary. + + + + Statements fired by triggers (both BEFORE and + AFTER) are annotated with + (trigger) in the output header. Their time is + tracked separately as Total Trigger Time and + excluded from Total Nested Time. Nested + statements that fire triggers also show + Trigger lines (name, time, call count) in their + plan output, matching the main query's trigger reporting format. + + + + When a function uses dynamic SQL via EXECUTE, + the Query Text field shows the actual executed + SQL string, not the PL/pgSQL source expression. + When VERBOSE is enabled and + compute_query_id is active, each nested statement + shows its Query Identifier, which can be used to + look up the statement in + pg_stat_statements. + @@ -575,6 +690,229 @@ EXPLAIN (GENERIC_PLAN) GROUP BY foo; + + + To display execution plans for nested statements within a function: + + +EXPLAIN (ANALYZE, NESTED_STATEMENTS) SELECT my_function(); + + QUERY PLAN +------------------------------------------------------------- + Result (cost=0.00..0.26 rows=1 width=4) (actual time=1.234..1.235 rows=1.00 loops=1) + Planning Time: 0.050 ms + Execution Time: 1.300 ms + + Nested Plans: + + Nested Statement #1 (level 1): + Query Text: SELECT count(*) FROM products + Aggregate (cost=11.75..11.76 rows=1 width=8) (actual time=0.200..0.201 rows=1.00 loops=1) + -> Seq Scan on products (cost=0.00..11.00 rows=500 width=0) (actual time=0.010..0.150 rows=500.00 loops=1) + Execution Time: 0.201 ms (20.1%) + + Nested Statement #2 (level 1): + Query Text: UPDATE products SET price = price * 1.10 WHERE category = 'Electronics' + Update on products (cost=0.00..12.50 rows=0 width=0) (actual time=0.800..0.800 rows=0.00 loops=1) + -> Seq Scan on products (cost=0.00..12.50 rows=50 width=10) (actual time=0.050..0.100 rows=50.00 loops=1) + Filter: (category = 'Electronics'::text) + Rows Removed by Filter: 450 + Execution Time: 0.800 ms (79.9%) + + Nested Statements Summary: + Total: 2 statements, max depth 1 + Total Execution Time: 1.300 ms + Total Nested Time: 1.001 ms (77.0% of total time) + Slowest Statement: #2 (0.800 ms, 79.9%) + + + This shows the main query plan followed by the execution plans for + each SQL statement executed inside my_function(). + + + + When triggers are involved, trigger-fired statements are annotated + and the parent statement shows trigger timing: + + +EXPLAIN (ANALYZE, NESTED_STATEMENTS, COSTS OFF) +UPDATE orders SET status = 'done' WHERE id = 1; + + QUERY PLAN +------------------------------------------------------------- + Update on orders (actual time=0.050..0.050 rows=0.00 loops=1) + -> Index Scan using orders_pkey on orders (...) + Trigger audit_trigger: time=0.522 calls=1 + Execution Time: 0.600 ms + + Nested Plans: + + Nested Statement #1 (level 1, trigger): + Query Text: INSERT INTO audit_log VALUES (NEW.id, 'status changed') + Insert on audit_log (actual time=0.010..0.010 rows=0.00 loops=1) + -> Result (actual time=0.001..0.001 rows=1.00 loops=1) + Execution Time: 0.011 ms + + Nested Statements Summary: + Total: 1 statements (0 direct, 1 trigger-fired), max depth 1 + Total Execution Time: 0.600 ms + Total Trigger Time: 0.011 ms + Slowest Statement: #1 (0.011 ms) + + + + + Use SHOW_NESTED to limit the number of plans displayed + when a function executes many statements: + + +EXPLAIN (ANALYZE, NESTED_STATEMENTS, SHOW_NESTED 1) SELECT my_function(); + + QUERY PLAN +------------------------------------------------------------- + Result (cost=0.00..0.26 rows=1 width=4) (actual time=1.234..1.235 rows=1.00 loops=1) + Planning Time: 0.050 ms + Execution Time: 1.300 ms + + Nested Plans (showing 1 of 2): + + Nested Statement #1 (level 1): + Query Text: SELECT count(*) FROM products + Aggregate (cost=11.75..11.76 rows=1 width=8) (actual time=0.200..0.201 rows=1.00 loops=1) + -> Seq Scan on products (cost=0.00..11.00 rows=500 width=0) (actual time=0.010..0.150 rows=500.00 loops=1) + Execution Time: 0.201 ms (20.1%) + + Nested Statements Summary: + Total: 2 statements, max depth 1 + Total Execution Time: 1.300 ms + Total Nested Time: 1.001 ms (77.0% of total time) + Slowest Statement: #2 (0.800 ms, 79.9%) + + + Only the first plan is shown, but the summary still reflects all + statements. Use SHOW_NESTED 0 to display only + the summary without any individual plans. + + + + 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: + + +EXPLAIN (ANALYZE, NESTED_STATEMENTS, FORMAT JSON) SELECT my_function(); + + QUERY PLAN +------------------------------------------------------------- +[ + { + "Plan": { + "Node Type": "Result", + "Startup Cost": 0.00, + "Total Cost": 0.26, + "Plan Rows": 1, + "Plan Width": 4, + "Actual Startup Time": 1.234, + "Actual Total Time": 1.235, + "Actual Rows": 1, + "Actual Loops": 1 + }, + "Planning Time": 0.050, + "Execution Time": 1.300 + } +] + +Nested Plans: + +Nested Statement #1 (level 1): +Query Text: SELECT count(*) FROM products +[ + { + "Plan": { + "Node Type": "Aggregate", + "Startup Cost": 11.75, + "Total Cost": 11.76, + "Plan Rows": 1, + "Plan Width": 8, + "Actual Startup Time": 0.200, + "Actual Total Time": 0.201, + "Actual Rows": 1, + "Actual Loops": 1, + "Plans": [ + { + "Node Type": "Seq Scan", + "Parent Relationship": "Outer", + "Relation Name": "products", + "Alias": "products", + "Startup Cost": 0.00, + "Total Cost": 11.00, + "Plan Rows": 500, + "Plan Width": 0, + "Actual Startup Time": 0.010, + "Actual Total Time": 0.150, + "Actual Rows": 500, + "Actual Loops": 1 + } + ] + }, + "Execution Time": 0.201 + } +] + +Nested Statement #2 (level 1): +Query Text: UPDATE products SET price = price * 1.10 WHERE category = 'Electronics' +[ + { + "Plan": { + "Node Type": "ModifyTable", + "Operation": "Update", + "Relation Name": "products", + "Alias": "products", + "Startup Cost": 0.00, + "Total Cost": 12.50, + "Plan Rows": 0, + "Plan Width": 0, + "Actual Startup Time": 0.800, + "Actual Total Time": 0.800, + "Actual Rows": 0, + "Actual Loops": 1, + "Plans": [ + { + "Node Type": "Seq Scan", + "Parent Relationship": "Outer", + "Relation Name": "products", + "Alias": "products", + "Startup Cost": 0.00, + "Total Cost": 12.50, + "Plan Rows": 50, + "Plan Width": 10, + "Actual Startup Time": 0.050, + "Actual Total Time": 0.100, + "Actual Rows": 50, + "Actual Loops": 1, + "Filter": "(category = 'Electronics'::text)", + "Rows Removed by Filter": 450 + } + ] + }, + "Execution Time": 0.800 + } +] + +Nested Statements Summary: + Total: 2 statements, max depth 1 + Total Execution Time: 1.300 ms + Total Nested Time: 1.001 ms (77.0% of total time) + Slowest Statement: #2 (0.800 ms, 79.9%) + + + 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 + Execution Time field is included inside each nested + plan's JSON structure when SUMMARY is enabled. + Percentages are shown only in the text-format summary, not inside the + structured plan objects. + diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 112c17b0d64..222583000f0 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -23,6 +23,8 @@ #include "commands/explain_format.h" #include "commands/explain_state.h" #include "commands/prepare.h" +#include "commands/trigger.h" +#include "executor/executor.h" #include "foreign/fdwapi.h" #include "jit/jit.h" #include "libpq/pqformat.h" @@ -58,6 +60,49 @@ explain_get_index_name_hook_type explain_get_index_name_hook = NULL; explain_per_plan_hook_type explain_per_plan_hook = NULL; explain_per_node_hook_type explain_per_node_hook = NULL; +/* Nested statements tracking for EXPLAIN (NESTED_STATEMENTS) */ +typedef struct NestedPlanInfo +{ + int statement_num; + int nesting_level; + char *query_text; + char *plan_text; + double exec_time_ms; /* execution time in ms, -1 if unavailable */ + bool is_trigger; /* true if fired by a trigger */ + struct NestedPlanInfo *next; +} NestedPlanInfo; + +static int nested_exec_level = 0; +static bool nested_tracking_active = false; +static ExplainState *nested_parent_es = NULL; +static int nested_stmt_count = 0; +static int nested_total_count = 0; +static int nested_max_depth = 0; +static double nested_total_time = 0.0; +static double nested_slowest_time = 0.0; +static int nested_slowest_num = 0; +static double nested_main_exec_time = 0.0; +static double nested_trigger_time = 0.0; +static int nested_trigger_count = 0; +static NestedPlanInfo *nested_plans_head = NULL; +static NestedPlanInfo *nested_plans_tail = NULL; +static MemoryContext nested_memcxt = NULL; + +/* Saved executor hook values for nested statements */ +static ExecutorStart_hook_type prev_ExecutorStart_hook = NULL; +static ExecutorRun_hook_type prev_ExecutorRun_hook = NULL; +static ExecutorFinish_hook_type prev_ExecutorFinish_hook = NULL; +static ExecutorEnd_hook_type prev_ExecutorEnd_hook = NULL; + +static void nested_ExecutorStart(QueryDesc *queryDesc, int eflags); +static void nested_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, + uint64 count); +static void nested_ExecutorFinish(QueryDesc *queryDesc); +static void nested_ExecutorEnd(QueryDesc *queryDesc); +static void ExplainPrintNestedPlans(ExplainState *es); +static void ExplainInstallNestedHooks(ExplainState *es); +static void ExplainRemoveNestedHooks(void); + /* * Various places within need to convert bytes to kilobytes. Round these up * to the next whole kilobyte. @@ -206,49 +251,74 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt, */ rewritten = QueryRewrite(castNode(Query, stmt->query)); - /* emit opening boilerplate */ - ExplainBeginOutput(es); + /* Install nested statement hooks if requested */ + if (es->nested_statements) + ExplainInstallNestedHooks(es); - if (rewritten == NIL) + PG_TRY(); { - /* - * In the case of an INSTEAD NOTHING, tell at least that. But in - * non-text format, the output is delimited, so this isn't necessary. - */ - if (es->format == EXPLAIN_FORMAT_TEXT) - appendStringInfoString(es->str, "Query rewrites to nothing\n"); - } - else - { - ListCell *l; + /* emit opening boilerplate */ + ExplainBeginOutput(es); - /* Explain every plan */ - foreach(l, rewritten) + if (rewritten == NIL) { - ExplainOneQuery(lfirst_node(Query, l), - CURSOR_OPT_PARALLEL_OK, NULL, es, - pstate, params); + /* + * In the case of an INSTEAD NOTHING, tell at least that. But in + * non-text format, the output is delimited, so this isn't necessary. + */ + if (es->format == EXPLAIN_FORMAT_TEXT) + appendStringInfoString(es->str, "Query rewrites to nothing\n"); + } + else + { + ListCell *l; + + /* Explain every plan */ + foreach(l, rewritten) + { + ExplainOneQuery(lfirst_node(Query, l), + CURSOR_OPT_PARALLEL_OK, NULL, es, + pstate, params); - /* Separate plans with an appropriate separator */ - if (lnext(rewritten, l) != NULL) - ExplainSeparatePlans(es); + /* Separate plans with an appropriate separator */ + if (lnext(rewritten, l) != NULL) + ExplainSeparatePlans(es); + } } - } - /* emit closing boilerplate */ - ExplainEndOutput(es); - Assert(es->indent == 0); + /* emit closing boilerplate */ + ExplainEndOutput(es); + Assert(es->indent == 0); - /* output tuples */ - tstate = begin_tup_output_tupdesc(dest, ExplainResultDesc(stmt), - &TTSOpsVirtual); - if (es->format == EXPLAIN_FORMAT_TEXT) - do_text_output_multiline(tstate, es->str->data); - else - do_text_output_oneline(tstate, es->str->data); - end_tup_output(tstate); + /* Print nested statement plans after main plan is complete */ + if (es->nested_statements) + ExplainPrintNestedPlans(es); + + /* output tuples */ + tstate = begin_tup_output_tupdesc(dest, ExplainResultDesc(stmt), + &TTSOpsVirtual); + if (es->format == EXPLAIN_FORMAT_TEXT) + do_text_output_multiline(tstate, es->str->data); + else + do_text_output_oneline(tstate, es->str->data); + end_tup_output(tstate); - pfree(es->str->data); + pfree(es->str->data); + } + PG_FINALLY(); + { + /* Always clean up nested statement hooks and memory */ + if (es->nested_statements) + { + ExplainRemoveNestedHooks(); + if (nested_memcxt) + { + MemoryContextDelete(nested_memcxt); + nested_memcxt = NULL; + } + } + } + PG_END_TRY(); } /* @@ -686,6 +756,10 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, ExplainPropertyFloat("Execution Time", "ms", 1000.0 * totaltime, 3, es); + /* Store main execution time for nested statements percentage calculation */ + if (es->nested_statements && nested_tracking_active) + nested_main_exec_time = 1000.0 * totaltime; + ExplainCloseGroup("Query", NULL, true, es); } @@ -5322,3 +5396,472 @@ ExplainFlushWorkersState(ExplainState *es) pfree(wstate->worker_state_save); pfree(wstate); } + +/* + * ExplainInstallNestedHooks - install executor hooks for nested statement + * tracking. + * + * This sets up hooks to intercept ExecutorStart, ExecutorRun, + * ExecutorFinish, and ExecutorEnd calls so we can track nesting depth + * and capture plans for nested statements. + */ +static void +ExplainInstallNestedHooks(ExplainState *es) +{ + /* + * Guard against reentrancy: if we're already tracking nested statements + * (e.g., a function executes EXPLAIN (NESTED_STATEMENTS) internally), + * skip hook installation to avoid corrupting the outer EXPLAIN's state. + */ + if (nested_tracking_active) + { + es->nested_statements = false; + return; + } + + nested_tracking_active = true; + nested_exec_level = 0; + nested_stmt_count = 0; + nested_total_count = 0; + nested_max_depth = 0; + nested_total_time = 0.0; + nested_slowest_time = 0.0; + nested_slowest_num = 0; + nested_main_exec_time = 0.0; + nested_trigger_time = 0.0; + nested_trigger_count = 0; + nested_plans_head = NULL; + nested_plans_tail = NULL; + nested_parent_es = es; + + /* + * Create a dedicated memory context for captured plan text. This ensures + * all allocations can be freed at once in the PG_FINALLY cleanup, whether + * the EXPLAIN succeeds or errors out. + */ + nested_memcxt = AllocSetContextCreate(CurrentMemoryContext, + "Nested EXPLAIN plans", + ALLOCSET_DEFAULT_SIZES); + + /* Save and install hooks */ + prev_ExecutorStart_hook = ExecutorStart_hook; + ExecutorStart_hook = nested_ExecutorStart; + prev_ExecutorRun_hook = ExecutorRun_hook; + ExecutorRun_hook = nested_ExecutorRun; + prev_ExecutorFinish_hook = ExecutorFinish_hook; + ExecutorFinish_hook = nested_ExecutorFinish; + prev_ExecutorEnd_hook = ExecutorEnd_hook; + ExecutorEnd_hook = nested_ExecutorEnd; +} + +/* + * ExplainRemoveNestedHooks - restore previous executor hooks. + */ +static void +ExplainRemoveNestedHooks(void) +{ + ExecutorStart_hook = prev_ExecutorStart_hook; + ExecutorRun_hook = prev_ExecutorRun_hook; + ExecutorFinish_hook = prev_ExecutorFinish_hook; + ExecutorEnd_hook = prev_ExecutorEnd_hook; + + prev_ExecutorStart_hook = NULL; + prev_ExecutorRun_hook = NULL; + prev_ExecutorFinish_hook = NULL; + prev_ExecutorEnd_hook = NULL; + + nested_tracking_active = false; + nested_parent_es = NULL; +} + +/* + * nested_ExecutorStart - ExecutorStart hook for nested statement tracking. + * + * When we're inside a nested execution (nesting_level > 0), enable + * instrumentation so we can capture actual execution statistics. + */ +static void +nested_ExecutorStart(QueryDesc *queryDesc, int eflags) +{ + if (nested_tracking_active && nested_exec_level > 0 && + (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0) + { + /* Enable per-node instrumentation for nested statements */ + if (nested_parent_es->timing) + queryDesc->instrument_options |= INSTRUMENT_TIMER; + else + queryDesc->instrument_options |= INSTRUMENT_ROWS; + if (nested_parent_es->buffers) + queryDesc->instrument_options |= INSTRUMENT_BUFFERS; + if (nested_parent_es->wal) + queryDesc->instrument_options |= INSTRUMENT_WAL; + + /* Enable query-level instrumentation for execution time tracking */ + queryDesc->query_instr_options |= INSTRUMENT_TIMER; + } + + if (prev_ExecutorStart_hook) + prev_ExecutorStart_hook(queryDesc, eflags); + else + standard_ExecutorStart(queryDesc, eflags); +} + +/* + * nested_ExecutorRun - ExecutorRun hook for nested statement tracking. + * + * Track nesting depth so we know when we're inside a nested execution. + */ +static void +nested_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count) +{ + nested_exec_level++; + PG_TRY(); + { + if (prev_ExecutorRun_hook) + prev_ExecutorRun_hook(queryDesc, direction, count); + else + standard_ExecutorRun(queryDesc, direction, count); + } + PG_FINALLY(); + { + nested_exec_level--; + } + PG_END_TRY(); +} + +/* + * nested_ExecutorFinish - ExecutorFinish hook for nested statement tracking. + * + * Track nesting depth through ExecutorFinish as well, since some statements + * (e.g., those with AFTER triggers) do work here. + */ +static void +nested_ExecutorFinish(QueryDesc *queryDesc) +{ + nested_exec_level++; + PG_TRY(); + { + if (prev_ExecutorFinish_hook) + prev_ExecutorFinish_hook(queryDesc); + else + standard_ExecutorFinish(queryDesc); + } + PG_FINALLY(); + { + nested_exec_level--; + } + PG_END_TRY(); +} + +/* + * nested_ExecutorEnd - ExecutorEnd hook for nested statement tracking. + * + * When a nested statement finishes execution, capture its plan text + * for later display. Uses GetMyTriggerDepth() to detect whether the + * statement was fired by a trigger (both BEFORE and AFTER). + */ +static void +nested_ExecutorEnd(QueryDesc *queryDesc) +{ + if (nested_tracking_active && + nested_exec_level > 0 && + nested_parent_es != NULL && + queryDesc->plannedstmt != NULL && + queryDesc->instrument_options != 0) + { + double stmt_time = -1.0; + bool is_trigger = (GetMyTriggerDepth() > 0); + + nested_total_count++; + if (is_trigger) + nested_trigger_count++; + + /* Track timing for summary (always, even if not displaying) */ + if (queryDesc->query_instr) + { + stmt_time = INSTR_TIME_GET_MILLISEC(queryDesc->query_instr->total); + if (is_trigger && nested_exec_level == 1) + { + /* + * Only sum level-1 trigger statements into Total Trigger Time. + * A level-1 trigger's inclusive time already contains any + * cascading triggers at deeper levels. + */ + nested_trigger_time += stmt_time; + } + else if (!is_trigger && nested_exec_level == 1) + { + /* + * Only sum level-1 statements into Total Nested Time. + * Level-1 statements already include deeper levels' time + * (inclusive timing), so summing all levels would + * double-count. + */ + nested_total_time += stmt_time; + } + if (!is_trigger && nested_exec_level == 1 && + stmt_time > nested_slowest_time) + { + nested_slowest_time = stmt_time; + nested_slowest_num = nested_total_count; + } + } + + /* Track max depth */ + if (nested_exec_level > nested_max_depth) + nested_max_depth = nested_exec_level; + + /* + * Only capture plan text if under the display limit. + * show_nested < 0 means show all (no limit). + */ + if (nested_parent_es->show_nested < 0 || + nested_stmt_count < nested_parent_es->show_nested) + { + MemoryContext oldcxt; + NestedPlanInfo *plan_info; + ExplainState *nes; + + nested_stmt_count++; + + /* + * Switch to the dedicated memory context so the captured plan + * text survives until we print it. + */ + oldcxt = MemoryContextSwitchTo(nested_memcxt); + + /* Build an ExplainState to format this nested plan */ + nes = NewExplainState(); + nes->analyze = true; + nes->verbose = nested_parent_es->verbose; + nes->costs = nested_parent_es->costs; + nes->buffers = nested_parent_es->buffers; + nes->wal = nested_parent_es->wal; + nes->timing = nested_parent_es->timing; + nes->summary = false; + nes->format = nested_parent_es->format; + + ExplainBeginOutput(nes); + ExplainOpenGroup("Query", NULL, true, nes); + ExplainPrintPlan(nes, queryDesc); + + /* Print trigger info for this nested statement (matches + * what top-level EXPLAIN does for the main query) */ + if (nes->analyze) + ExplainPrintTriggers(nes, queryDesc); + + /* Add Execution Time inside structured output for non-TEXT */ + if (nes->format != EXPLAIN_FORMAT_TEXT && + queryDesc->query_instr && + nested_parent_es->summary) + ExplainPropertyFloat("Execution Time", "ms", stmt_time, 3, nes); + + ExplainCloseGroup("Query", NULL, true, nes); + ExplainEndOutput(nes); + + /* Remove trailing newline if present */ + if (nes->str->len > 0 && nes->str->data[nes->str->len - 1] == '\n') + nes->str->data[--nes->str->len] = '\0'; + + /* Allocate and fill the plan info node */ + plan_info = (NestedPlanInfo *) palloc(sizeof(NestedPlanInfo)); + plan_info->statement_num = nested_total_count; + plan_info->nesting_level = nested_exec_level; + plan_info->query_text = queryDesc->sourceText ? + pstrdup(queryDesc->sourceText) : pstrdup(""); + plan_info->plan_text = pstrdup(nes->str->data); + plan_info->exec_time_ms = stmt_time; + plan_info->is_trigger = is_trigger; + plan_info->next = NULL; + + /* Append to the linked list */ + if (nested_plans_tail == NULL) + { + nested_plans_head = plan_info; + nested_plans_tail = plan_info; + } + else + { + nested_plans_tail->next = plan_info; + nested_plans_tail = plan_info; + } + + MemoryContextSwitchTo(oldcxt); + } + } + + if (prev_ExecutorEnd_hook) + prev_ExecutorEnd_hook(queryDesc); + else + standard_ExecutorEnd(queryDesc); +} + +/* + * ExplainPrintNestedPlans - print collected nested statement plans. + * + * This is called after the main query plan has been printed, to append + * the nested statement plans to the EXPLAIN output. + */ +static void +ExplainPrintNestedPlans(ExplainState *es) +{ + NestedPlanInfo *info; + + if (nested_plans_head == NULL && nested_total_count == 0) + return; + + if (es->format == EXPLAIN_FORMAT_TEXT) + { + appendStringInfoChar(es->str, '\n'); + if (nested_total_count > nested_stmt_count) + appendStringInfo(es->str, "Nested Plans (showing %d of %d):\n", + nested_stmt_count, nested_total_count); + else + appendStringInfoString(es->str, "Nested Plans:\n"); + + for (info = nested_plans_head; info != NULL; info = info->next) + { + appendStringInfoChar(es->str, '\n'); + if (info->is_trigger) + appendStringInfo(es->str, " Nested Statement #%d (level %d, trigger):\n", + info->statement_num, info->nesting_level); + else + appendStringInfo(es->str, " Nested Statement #%d (level %d):\n", + info->statement_num, info->nesting_level); + appendStringInfo(es->str, " Query Text: %s\n", info->query_text); + + /* Indent the plan text */ + { + char *line; + char *plan_copy = pstrdup(info->plan_text); + char *saveptr = NULL; + + for (line = strtok_r(plan_copy, "\n", &saveptr); + line != NULL; + line = strtok_r(NULL, "\n", &saveptr)) + { + appendStringInfo(es->str, " %s\n", line); + } + pfree(plan_copy); + } + + /* Print execution time if available and summary is enabled */ + if (info->exec_time_ms >= 0 && es->summary) + { + if (info->is_trigger) + { + /* Trigger time is included in parent's time; + * header already shows "(trigger)" annotation */ + appendStringInfo(es->str, " Execution Time: %.3f ms\n", + info->exec_time_ms); + } + else if (info->nesting_level == 1 && nested_total_time > 0) + { + /* + * Only level-1 statements show percentage, since + * Total Nested Time sums only level-1 times. + * Deeper statements show absolute time only (their + * time is already included in their level-1 parent). + */ + double pct = (info->exec_time_ms / nested_total_time) * 100.0; + appendStringInfo(es->str, " Execution Time: %.3f ms (%.1f%%)\n", + info->exec_time_ms, pct); + } + else + appendStringInfo(es->str, " Execution Time: %.3f ms\n", + info->exec_time_ms); + } + } + } + else + { + /* For structured formats (JSON, XML, YAML) — append each nested + * plan as its own structured block after the main plan */ + if (nested_total_count > nested_stmt_count) + appendStringInfo(es->str, "\n\nNested Plans (showing %d of %d):\n", + nested_stmt_count, nested_total_count); + else + appendStringInfoString(es->str, "\n\nNested Plans:\n"); + + for (info = nested_plans_head; info != NULL; info = info->next) + { + appendStringInfoChar(es->str, '\n'); + if (info->is_trigger) + appendStringInfo(es->str, "Nested Statement #%d (level %d, trigger):\n", + info->statement_num, info->nesting_level); + else + appendStringInfo(es->str, "Nested Statement #%d (level %d):\n", + info->statement_num, info->nesting_level); + appendStringInfo(es->str, "Query Text: %s\n", info->query_text); + /* Append the structured plan output (already in JSON/XML/YAML, + * with Execution Time included inside the structure) */ + appendStringInfoString(es->str, info->plan_text); + appendStringInfoChar(es->str, '\n'); + } + } + + /* Print summary if enabled */ + if (es->summary && nested_total_count > 0) + { + int direct_count = nested_total_count - nested_trigger_count; + + appendStringInfoChar(es->str, '\n'); + appendStringInfoString(es->str, "Nested Statements Summary:\n"); + + if (nested_trigger_count > 0) + appendStringInfo(es->str, " Total: %d statements (%d direct, %d trigger-fired), max depth %d\n", + nested_total_count, direct_count, + nested_trigger_count, nested_max_depth); + else + appendStringInfo(es->str, " Total: %d statements, max depth %d\n", + nested_total_count, nested_max_depth); + + if (nested_main_exec_time > 0) + appendStringInfo(es->str, " Total Execution Time: %.3f ms\n", + nested_main_exec_time); + + if (nested_total_time > 0) + { + if (nested_main_exec_time > 0) + { + double pct = (nested_total_time / nested_main_exec_time) * 100.0; + appendStringInfo(es->str, " Total Nested Time: %.3f ms (%.1f%% of total time)\n", + nested_total_time, pct); + } + else + appendStringInfo(es->str, " Total Nested Time: %.3f ms\n", + nested_total_time); + } + + if (nested_trigger_time > 0) + { + if (nested_total_time > 0) + { + double pct = (nested_trigger_time / nested_total_time) * 100.0; + appendStringInfo(es->str, " Total Trigger Time: %.3f ms (%.1f%% of nested time)\n", + nested_trigger_time, pct); + } + else + appendStringInfo(es->str, " Total Trigger Time: %.3f ms\n", + nested_trigger_time); + } + + if (nested_slowest_num > 0) + { + if (nested_total_time > 0) + { + double pct = (nested_slowest_time / nested_total_time) * 100.0; + appendStringInfo(es->str, " Slowest Statement: #%d (%.3f ms, %.1f%%)\n", + nested_slowest_num, nested_slowest_time, pct); + } + else + appendStringInfo(es->str, " Slowest Statement: #%d (%.3f ms)\n", + nested_slowest_num, nested_slowest_time); + } + } + + /* No need to free individual items — MemoryContextDelete in PG_FINALLY + * will free everything in nested_memcxt at once. */ + nested_plans_head = NULL; + nested_plans_tail = NULL; +} diff --git a/src/backend/commands/explain_state.c b/src/backend/commands/explain_state.c index a0ee0a664be..73bce1b350c 100644 --- a/src/backend/commands/explain_state.c +++ b/src/backend/commands/explain_state.c @@ -67,6 +67,7 @@ NewExplainState(void) /* Set default options (most fields can be left as zeroes). */ es->costs = true; + es->show_nested = -1; /* show all nested plans by default */ /* Prepare output buffer. */ es->str = makeStringInfo(); @@ -164,6 +165,17 @@ ParseExplainOptionList(ExplainState *es, List *options, ParseState *pstate) } else if (strcmp(opt->defname, "io") == 0) es->io = defGetBoolean(opt); + else if (strcmp(opt->defname, "nested_statements") == 0) + es->nested_statements = defGetBoolean(opt); + else if (strcmp(opt->defname, "show_nested") == 0) + { + es->show_nested = defGetInt32(opt); + if (es->show_nested < 0) + ereport(ERROR, + (errcode(ERRCODE_INVALID_PARAMETER_VALUE), + errmsg("EXPLAIN option %s must be a non-negative integer", + "SHOW_NESTED"))); + } else if (!ApplyExtensionExplainOption(es, opt, pstate)) ereport(ERROR, (errcode(ERRCODE_SYNTAX_ERROR), @@ -202,6 +214,19 @@ ParseExplainOptionList(ExplainState *es, List *options, ParseState *pstate) (errcode(ERRCODE_INVALID_PARAMETER_VALUE), errmsg("EXPLAIN option %s requires ANALYZE", "SERIALIZE"))); + /* check that NESTED_STATEMENTS is used with EXPLAIN ANALYZE */ + if (es->nested_statements && !es->analyze) + ereport(ERROR, + (errcode(ERRCODE_INVALID_PARAMETER_VALUE), + errmsg("EXPLAIN option %s requires ANALYZE", "NESTED_STATEMENTS"))); + + /* check that SHOW_NESTED is used with NESTED_STATEMENTS */ + if (es->show_nested >= 0 && !es->nested_statements) + ereport(ERROR, + (errcode(ERRCODE_INVALID_PARAMETER_VALUE), + errmsg("EXPLAIN option %s requires %s", + "SHOW_NESTED", "NESTED_STATEMENTS"))); + /* check that GENERIC_PLAN is not used with EXPLAIN ANALYZE */ if (es->generic && es->analyze) ereport(ERROR, diff --git a/src/backend/commands/trigger.c b/src/backend/commands/trigger.c index b87b4b40d07..097ddf800b0 100644 --- a/src/backend/commands/trigger.c +++ b/src/backend/commands/trigger.c @@ -6783,10 +6783,26 @@ assign_session_replication_role(int newval, void *extra) /* * SQL function pg_trigger_depth() */ +/* + * GetMyTriggerDepth - return current trigger nesting depth. + * + * This is a C-callable accessor for MyTriggerDepth, allowing other + * subsystems (e.g., EXPLAIN NESTED_STATEMENTS) to detect whether + * execution is currently inside a trigger function. + */ +int +GetMyTriggerDepth(void) +{ + return MyTriggerDepth; +} + +/* + * SQL-callable function to report trigger nesting depth. + */ Datum pg_trigger_depth(PG_FUNCTION_ARGS) { - PG_RETURN_INT32(MyTriggerDepth); + PG_RETURN_INT32(GetMyTriggerDepth()); } /* diff --git a/src/include/commands/explain_state.h b/src/include/commands/explain_state.h index 97bc7ed49f6..01fef3068b6 100644 --- a/src/include/commands/explain_state.h +++ b/src/include/commands/explain_state.h @@ -57,6 +57,8 @@ typedef struct ExplainState bool settings; /* print modified settings */ bool io; /* print info about IO (prefetch, ...) */ bool generic; /* generate a generic plan */ + bool nested_statements; /* print nested statement plans */ + int show_nested; /* how many nested plans to display (-1=all) */ ExplainSerializeOption serialize; /* serialize the query's output? */ ExplainFormat format; /* output format */ /* state for output formatting --- not reset for each new plan tree */ diff --git a/src/include/commands/trigger.h b/src/include/commands/trigger.h index 1d9869973c0..83c97141876 100644 --- a/src/include/commands/trigger.h +++ b/src/include/commands/trigger.h @@ -310,4 +310,6 @@ extern void RegisterAfterTriggerBatchCallback(AfterTriggerBatchCallback callback void *arg); extern bool AfterTriggerIsActive(void); +extern int GetMyTriggerDepth(void); + #endif /* TRIGGER_H */ -- 2.50.1 (Apple Git-155)