From 2195695627ea3f127937b3c066c157b475127c6c Mon Sep 17 00:00:00 2001 From: rafaelthca Date: Tue, 7 Jan 2025 19:32:16 +0000 Subject: [PATCH v5] Proposal for progressive explains This proposal introduces a feature to print execution plans of active queries in an in-memory shared hash object so that other sessions can visualize via new view pg_stat_progress_explain. Plans are only printed if new GUC parameter progressive_explain is enabled. When progressive_explain is set to 'explain' the plan will be printed only once at the beginning of the query. If set to 'analyze' the QueryDesc will be adjusted adding instrumentation flags. In that case the plan will be printed on a fixed interval controlled by new GUC parameter progressive_explain_interval including all instrumentation stats computed so far (per node rows and execution time). New view: - pg_stat_progress_explain - pid: PID of the process running the query - last_print: timestamp when plan was last printed - query_plan: the actual plan (limited read privileges) New GUCs: - progressive_explain: if progressive plans are printed for local session. - type: enum - default: off - values: [off, explain, analyze] - context: user - progressive_explain_interval: interval between each explain print. - type: int - default: 1s - min: 10ms - context: user - progressive_explain_format: format used to print the plans. - type: enum - default: text - values: [TEXT, XML, JSON, or YAML] - context: user - progressive_explain_settings: controls whether information about modified configuration is added to the printed plan. - type: bool - default: off - context: user - progressive_explain_verbose: controls whether verbose details are added to the printed plan. - type: bool - default: off - context: user - progressive_explain_buffers: controls whether buffers details are added to the printed plan. - type: bool - default: off - context: user - progressive_explain_timing: controls whether per node timing details are added to the printed plan. - type: bool - default: off - context: user - progressive_explain_wal: controls whether WAL record generation details are added to the printed plan. - type: bool - default: off - context: user --- doc/src/sgml/config.sgml | 120 ++++ doc/src/sgml/monitoring.sgml | 64 ++ doc/src/sgml/perform.sgml | 95 +++ src/backend/catalog/system_views.sql | 5 + src/backend/commands/explain.c | 580 ++++++++++++++++-- src/backend/executor/execMain.c | 24 + src/backend/executor/execProcnode.c | 36 +- src/backend/executor/instrument.c | 20 +- src/backend/storage/ipc/ipci.c | 7 + src/backend/storage/lmgr/lwlock.c | 1 + .../utils/activity/wait_event_names.txt | 1 + src/backend/utils/init/postinit.c | 10 + src/backend/utils/misc/guc_tables.c | 112 ++++ src/backend/utils/misc/postgresql.conf.sample | 12 + src/include/catalog/pg_proc.dat | 10 + src/include/commands/explain.h | 42 ++ src/include/executor/execdesc.h | 1 + src/include/executor/instrument.h | 1 + src/include/nodes/execnodes.h | 4 + src/include/storage/lwlock.h | 1 + src/include/storage/lwlocklist.h | 1 + src/include/utils/guc.h | 8 + src/include/utils/timeout.h | 1 + src/test/regress/expected/rules.out | 4 + src/tools/pgindent/typedefs.list | 4 + 25 files changed, 1108 insertions(+), 56 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 336630ce417..ec44ccc693d 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -8411,6 +8411,126 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv; + + progressive_explain (enum) + + progressive_explain configuration parameter + + + + + Determines whether progressive explains are enabled and how + they are executed; see . + Possible values are off, explain + and analyze. The default is off. + + + + + + progressive_explain_buffers (boolean) + + progressive_explain_buffers configuration parameter + + + + + Controls whether information about buffers is added to + progressive explains. Equivalent to the BUFFERS option of + EXPLAIN. The default is off. + + + + + + progressive_explain_timing (boolean) + + progressive_explain_timing configuration parameter + + + + + Controls whether information about per node timing is added + to progressive explains. Equivalent to the TIMING option of + EXPLAIN. The default is off. + + + + + + progressive_explain_wal (boolean) + + progressive_explain_wal configuration parameter + + + + + Controls whether information about WAL record generation is + added to progressive explains. Equivalent to the WAL option of + EXPLAIN. The default is off. + + + + + + progressive_explain_verbose (boolean) + + progressive_explain_verbose configuration parameter + + + + + Controls whether verbose details are added to progressive explains. + Equivalent to the VERBOSE option of EXPLAIN. The default is + off. + + + + + + progressive_explain_settings (boolean) + + progressive_explain_settings configuration parameter + + + + + Controls whether information about modified configuration is added to + progressive explains. Equivalent to the SETTINGS option of EXPLAIN. + The default is off. + + + + + + progressive_explain_interval (integer) + + progressive_explain_interval configuration parameter + + + + + Sets the interval (in milliseconds) between each instrumented + progressive explain. The default is 1s. + + + + + + progressive_explain_format (enum) + + progressive_explain_format configuration parameter + + + + + Selects the EXPLAIN output format to be used with progressive + explains. Equivalent to the FORMAT option of EXPLAIN. The default + is text. + + + + diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index 928a6eb64b0..0a64ea78324 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -6818,6 +6818,70 @@ FROM pg_stat_get_backend_idset() AS backendid; + + EXPLAIN Progress Reporting + + + pg_stat_progress_explain + + + + Whenever a client backend or parallel worker is running a query with + enabled, the + pg_stat_progress_explain view will contain a + corresponding row with query plan details; see + . The table below describe the + information that will be reported. + + + + <structname>pg_stat_progress_explain</structname> View + + + + + Column Type + + + Description + + + + + + + + pid integer + + + Process ID of a client backend or parallel worker. + + + + + + last_print timestamp with time zone + + + Timestamp when plan was last printed. + + + + + + query_plan text + + + The progressive explain text. + + + + + +
+ + + diff --git a/doc/src/sgml/perform.sgml b/doc/src/sgml/perform.sgml index a502a2aaba3..349e8a66b65 100644 --- a/doc/src/sgml/perform.sgml +++ b/doc/src/sgml/perform.sgml @@ -1109,6 +1109,101 @@ EXPLAIN ANALYZE SELECT * FROM tenk1 WHERE unique1 < 100 AND unique2 > 9000 + + Progressive <command>EXPLAIN</command> + + + The query plan created by the planner for any given active query can + be visualized by any session via + view when is enabled in the + client backend or parallel worker executing query. Settings + , + and + control which additional + instrumentaton details are collected and included in the output while + , + and + + define how the plan is printed and which details are added there. + + + + When is set to explain + the plan will be printed once at the beginning of the query. + + + + +SET progressive_explain = 'explain'; +SET + +SELECT * FROM test t1 INNER JOIN test t2 ON t1.c1=t2.c1; + + + + +SELECT * FROM pg_stat_progress_explain; + pid | last_print | query_plan +------+-------------------------------+------------------------------------------------------------------------------ + 5307 | 2025-02-18 09:37:41.781459-03 | Hash Join (cost=327879.85..878413.95 rows=9999860 width=18) + + | | Hash Cond: (t1.c1 = t2.c1) + + | | -> Seq Scan on test t1 (cost=0.00..154053.60 rows=9999860 width=9) + + | | -> Hash (cost=154053.60..154053.60 rows=9999860 width=9) + + | | -> Seq Scan on test t2 (cost=0.00..154053.60 rows=9999860 width=9)+ + | | +(1 row) + + + + + Setting to analyze + will enable instrumentation and the detailed plan is printed on a fixed interval + controlled by , including + per node accumulated row count and other statistics. + + + + Progressive explains include additional information per node to help analyzing + execution progress: + + + + + current: the plan node currently being processed. + + + + + never executed: a plan node not processed yet. + + + + + + +SET progressive_explain = 'analyze'; +SET + +SELECT * FROM test t1 INNER JOIN test t2 ON t1.c1=t2.c1; + + + + +SELECT * FROM pg_stat_progress_explain; + pid | last_print | query_plan +------+-------------------------------+------------------------------------------------------------------------------------------------------------------------------------ + 5307 | 2025-02-18 09:36:03.580721-03 | Hash Join (cost=327879.85..878413.95 rows=9999860 width=18) (actual time=2010.504..2998.111 rows=38603 loops=1) + + | | Hash Cond: (t1.c1 = t2.c1) + + | | -> Seq Scan on test t1 (cost=0.00..154053.60 rows=9999860 width=9) (actual time=0.068..303.963 rows=4928320 loops=1) (current)+ + | | -> Hash (cost=154053.60..154053.60 rows=9999860 width=9) (actual time=2009.824..2009.824 rows=10000000 loops=1) + + | | -> Seq Scan on test t2 (cost=0.00..154053.60 rows=9999860 width=9) (actual time=0.035..640.890 rows=10000000 loops=1) + + | | +(1 row) + + + + + diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql index eff0990957e..445aa317ad0 100644 --- a/src/backend/catalog/system_views.sql +++ b/src/backend/catalog/system_views.sql @@ -1338,6 +1338,11 @@ CREATE VIEW pg_stat_progress_copy AS FROM pg_stat_get_progress_info('COPY') AS S LEFT JOIN pg_database D ON S.datid = D.oid; +CREATE VIEW pg_stat_progress_explain AS + SELECT + * + FROM pg_stat_progress_explain(true); + CREATE VIEW pg_user_mappings AS SELECT U.oid AS umid, diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index dc4bef9ab81..d89b71ff684 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -19,6 +19,7 @@ #include "commands/defrem.h" #include "commands/prepare.h" #include "foreign/fdwapi.h" +#include "funcapi.h" #include "jit/jit.h" #include "libpq/pqformat.h" #include "libpq/protocol.h" @@ -30,6 +31,7 @@ #include "rewrite/rewriteHandler.h" #include "storage/bufmgr.h" #include "tcop/tcopprot.h" +#include "utils/backend_status.h" #include "utils/builtins.h" #include "utils/guc_tables.h" #include "utils/json.h" @@ -37,17 +39,27 @@ #include "utils/rel.h" #include "utils/ruleutils.h" #include "utils/snapmgr.h" +#include "utils/timeout.h" #include "utils/tuplesort.h" #include "utils/typcache.h" #include "utils/xml.h" + + +#define PROGRESSIVE_EXPLAIN_ALLOC_SIZE 4096 + /* Hook for plugins to get control in ExplainOneQuery() */ ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL; /* Hook for plugins to get control in explain_get_index_name() */ explain_get_index_name_hook_type explain_get_index_name_hook = NULL; +/* Shared hash to store progressive explains */ +static HTAB *progressiveExplainArray = NULL; + +/* Flag set by timeouts to control when to print progressive explains */ +bool ProgressiveExplainPending = false; /* Instrumentation data for SERIALIZE option */ typedef struct SerializeMetrics @@ -140,7 +152,7 @@ static void show_hashagg_info(AggState *aggstate, ExplainState *es); static void show_tidbitmap_info(BitmapHeapScanState *planstate, ExplainState *es); static void show_instrumentation_count(const char *qlabel, int which, - PlanState *planstate, ExplainState *es); + Instrumentation *instr, ExplainState *es); static void show_foreignscan_info(ForeignScanState *fsstate, ExplainState *es); static const char *explain_get_index_name(Oid indexId); static bool peek_buffer_usage(ExplainState *es, const BufferUsage *usage); @@ -180,6 +192,9 @@ static void ExplainJSONLineEnding(ExplainState *es); static void ExplainYAMLLineStarting(ExplainState *es); static void escape_yaml(StringInfo buf, const char *str); static SerializeMetrics GetSerializationMetrics(DestReceiver *dest); +static void ProgressiveExplainPrint(QueryDesc *queryDesc); +static void ProgressiveExplainCleanup(dsa_area *a); +static void ProgressiveExplainReleaseFunc(void *); @@ -392,6 +407,8 @@ NewExplainState(void) es->costs = true; /* Prepare output buffer. */ es->str = makeStringInfo(); + /* An explain state is not progressive by default */ + es->progressive = false; return es; } @@ -1504,6 +1521,7 @@ ExplainNode(PlanState *planstate, List *ancestors, const char *partialmode = NULL; const char *operation = NULL; const char *custom_name = NULL; + Instrumentation *local_instr = NULL; ExplainWorkersState *save_workers_state = es->workers_state; int save_indent = es->indent; bool haschildren; @@ -1967,28 +1985,65 @@ ExplainNode(PlanState *planstate, List *ancestors, * instrumentation results the user didn't ask for. But we do the * InstrEndLoop call anyway, if possible, to reduce the number of cases * auto_explain has to contend with. + * + * For regular explains instrumentation clean up is called directly in the + * main instrumentation objects. Progressive explains need to clone + * instrumentation object and forcibly end the loop in nodes that may be + * running. */ if (planstate->instrument) - InstrEndLoop(planstate->instrument); + { + /* Progressive explain. Use auxiliary instrumentation object */ + if (es->progressive) + { + local_instr = es->pe_local_instr; + *local_instr = *planstate->instrument; + + /* Force end loop even if node is in progress */ + InstrEndLoopForce(local_instr); + } + /* Use main instrumentation */ + else + { + local_instr = planstate->instrument; + InstrEndLoop(local_instr); + } + } if (es->analyze && - planstate->instrument && planstate->instrument->nloops > 0) + local_instr && local_instr->nloops > 0) { - double nloops = planstate->instrument->nloops; - double startup_ms = 1000.0 * planstate->instrument->startup / nloops; - double total_ms = 1000.0 * planstate->instrument->total / nloops; - double rows = planstate->instrument->ntuples / nloops; + double nloops = local_instr->nloops; + double startup_ms = 1000.0 * local_instr->startup / nloops; + double total_ms = 1000.0 * local_instr->total / nloops; + double rows = local_instr->ntuples / nloops; if (es->format == EXPLAIN_FORMAT_TEXT) { if (es->timing) - appendStringInfo(es->str, - " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)", - startup_ms, total_ms, rows, nloops); + { + /* Node in progress */ + if (es->progressive && planstate == es->pe_curr_node) + appendStringInfo(es->str, + " (actual time=%.3f..%.3f rows=%.0f loops=%.0f) (current)", + startup_ms, total_ms, rows, nloops); + else + appendStringInfo(es->str, + " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)", + startup_ms, total_ms, rows, nloops); + } else - appendStringInfo(es->str, - " (actual rows=%.0f loops=%.0f)", - rows, nloops); + { + /* Node in progress */ + if (es->progressive && planstate == es->pe_curr_node) + appendStringInfo(es->str, + " (actual rows=%.0f loops=%.0f) (current)", + rows, nloops); + else + appendStringInfo(es->str, + " (actual rows=%.0f loops=%.0f)", + rows, nloops); + } } else { @@ -1999,6 +2054,9 @@ ExplainNode(PlanState *planstate, List *ancestors, ExplainPropertyFloat("Actual Total Time", "ms", total_ms, 3, es); } + /* Progressive explain. Add current node flag is applicable */ + if (es->progressive && planstate == es->pe_curr_node) + ExplainPropertyBool("Current", true, es); ExplainPropertyFloat("Actual Rows", NULL, rows, 0, es); ExplainPropertyFloat("Actual Loops", NULL, nloops, 0, es); } @@ -2107,29 +2165,29 @@ ExplainNode(PlanState *planstate, List *ancestors, "Index Cond", planstate, ancestors, es); if (((IndexScan *) plan)->indexqualorig) show_instrumentation_count("Rows Removed by Index Recheck", 2, - planstate, es); + local_instr, es); show_scan_qual(((IndexScan *) plan)->indexorderbyorig, "Order By", planstate, ancestors, es); show_scan_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, - planstate, es); + local_instr, es); break; case T_IndexOnlyScan: show_scan_qual(((IndexOnlyScan *) plan)->indexqual, "Index Cond", planstate, ancestors, es); if (((IndexOnlyScan *) plan)->recheckqual) show_instrumentation_count("Rows Removed by Index Recheck", 2, - planstate, es); + local_instr, es); show_scan_qual(((IndexOnlyScan *) plan)->indexorderby, "Order By", planstate, ancestors, es); show_scan_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, - planstate, es); + local_instr, es); if (es->analyze) ExplainPropertyFloat("Heap Fetches", NULL, - planstate->instrument->ntuples2, 0, es); + local_instr->ntuples2, 0, es); break; case T_BitmapIndexScan: show_scan_qual(((BitmapIndexScan *) plan)->indexqualorig, @@ -2140,11 +2198,11 @@ ExplainNode(PlanState *planstate, List *ancestors, "Recheck Cond", planstate, ancestors, es); if (((BitmapHeapScan *) plan)->bitmapqualorig) show_instrumentation_count("Rows Removed by Index Recheck", 2, - planstate, es); + local_instr, es); show_scan_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, - planstate, es); + local_instr, es); show_tidbitmap_info((BitmapHeapScanState *) planstate, es); break; case T_SampleScan: @@ -2161,7 +2219,7 @@ ExplainNode(PlanState *planstate, List *ancestors, show_scan_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, - planstate, es); + local_instr, es); if (IsA(plan, CteScan)) show_ctescan_info(castNode(CteScanState, planstate), es); break; @@ -2172,7 +2230,7 @@ ExplainNode(PlanState *planstate, List *ancestors, show_scan_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, - planstate, es); + local_instr, es); ExplainPropertyInteger("Workers Planned", NULL, gather->num_workers, es); @@ -2196,7 +2254,7 @@ ExplainNode(PlanState *planstate, List *ancestors, show_scan_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, - planstate, es); + local_instr, es); ExplainPropertyInteger("Workers Planned", NULL, gm->num_workers, es); @@ -2230,7 +2288,7 @@ ExplainNode(PlanState *planstate, List *ancestors, show_scan_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, - planstate, es); + local_instr, es); break; case T_TableFuncScan: if (es->verbose) @@ -2244,7 +2302,7 @@ ExplainNode(PlanState *planstate, List *ancestors, show_scan_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, - planstate, es); + local_instr, es); show_table_func_scan_info(castNode(TableFuncScanState, planstate), es); break; @@ -2262,7 +2320,7 @@ ExplainNode(PlanState *planstate, List *ancestors, show_scan_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, - planstate, es); + local_instr, es); } break; case T_TidRangeScan: @@ -2279,14 +2337,14 @@ ExplainNode(PlanState *planstate, List *ancestors, show_scan_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, - planstate, es); + local_instr, es); } break; case T_ForeignScan: show_scan_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, - planstate, es); + local_instr, es); show_foreignscan_info((ForeignScanState *) planstate, es); break; case T_CustomScan: @@ -2296,7 +2354,7 @@ ExplainNode(PlanState *planstate, List *ancestors, show_scan_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, - planstate, es); + local_instr, es); if (css->methods->ExplainCustomScan) css->methods->ExplainCustomScan(css, ancestors, es); } @@ -2306,11 +2364,11 @@ ExplainNode(PlanState *planstate, List *ancestors, "Join Filter", planstate, ancestors, es); if (((NestLoop *) plan)->join.joinqual) show_instrumentation_count("Rows Removed by Join Filter", 1, - planstate, es); + local_instr, es); show_upper_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 2, - planstate, es); + local_instr, es); break; case T_MergeJoin: show_upper_qual(((MergeJoin *) plan)->mergeclauses, @@ -2319,11 +2377,11 @@ ExplainNode(PlanState *planstate, List *ancestors, "Join Filter", planstate, ancestors, es); if (((MergeJoin *) plan)->join.joinqual) show_instrumentation_count("Rows Removed by Join Filter", 1, - planstate, es); + local_instr, es); show_upper_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 2, - planstate, es); + local_instr, es); break; case T_HashJoin: show_upper_qual(((HashJoin *) plan)->hashclauses, @@ -2332,11 +2390,11 @@ ExplainNode(PlanState *planstate, List *ancestors, "Join Filter", planstate, ancestors, es); if (((HashJoin *) plan)->join.joinqual) show_instrumentation_count("Rows Removed by Join Filter", 1, - planstate, es); + local_instr, es); show_upper_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 2, - planstate, es); + local_instr, es); break; case T_Agg: show_agg_keys(castNode(AggState, planstate), ancestors, es); @@ -2344,13 +2402,13 @@ ExplainNode(PlanState *planstate, List *ancestors, show_hashagg_info((AggState *) planstate, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, - planstate, es); + local_instr, es); break; case T_WindowAgg: show_upper_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, - planstate, es); + local_instr, es); show_upper_qual(((WindowAgg *) plan)->runConditionOrig, "Run Condition", planstate, ancestors, es); show_windowagg_info(castNode(WindowAggState, planstate), es); @@ -2360,7 +2418,7 @@ ExplainNode(PlanState *planstate, List *ancestors, show_upper_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, - planstate, es); + local_instr, es); break; case T_Sort: show_sort_keys(castNode(SortState, planstate), ancestors, es); @@ -2382,7 +2440,7 @@ ExplainNode(PlanState *planstate, List *ancestors, show_upper_qual(plan->qual, "Filter", planstate, ancestors, es); if (plan->qual) show_instrumentation_count("Rows Removed by Filter", 1, - planstate, es); + local_instr, es); break; case T_ModifyTable: show_modifytable_info(castNode(ModifyTableState, planstate), ancestors, @@ -2427,10 +2485,10 @@ ExplainNode(PlanState *planstate, List *ancestors, } /* Show buffer/WAL usage */ - if (es->buffers && planstate->instrument) - show_buffer_usage(es, &planstate->instrument->bufusage); - if (es->wal && planstate->instrument) - show_wal_usage(es, &planstate->instrument->walusage); + if (es->buffers && local_instr) + show_buffer_usage(es, &local_instr->bufusage); + if (es->wal && local_instr) + show_wal_usage(es, &local_instr->walusage); /* Prepare per-worker buffer/WAL usage */ if (es->workers_state && (es->buffers || es->wal) && es->verbose) @@ -3947,19 +4005,19 @@ show_tidbitmap_info(BitmapHeapScanState *planstate, ExplainState *es) */ static void show_instrumentation_count(const char *qlabel, int which, - PlanState *planstate, ExplainState *es) + Instrumentation *instr, ExplainState *es) { double nfiltered; double nloops; - if (!es->analyze || !planstate->instrument) + if (!es->analyze || !instr) return; if (which == 2) - nfiltered = planstate->instrument->nfiltered2; + nfiltered = instr->nfiltered2; else - nfiltered = planstate->instrument->nfiltered1; - nloops = planstate->instrument->nloops; + nfiltered = instr->nfiltered1; + nloops = instr->nloops; /* In text mode, suppress zero counts; they're not interesting enough */ if (nfiltered > 0 || es->format != EXPLAIN_FORMAT_TEXT) @@ -4630,7 +4688,7 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors, { show_upper_qual((List *) node->onConflictWhere, "Conflict Filter", &mtstate->ps, ancestors, es); - show_instrumentation_count("Rows Removed by Conflict Filter", 1, &mtstate->ps, es); + show_instrumentation_count("Rows Removed by Conflict Filter", 1, (&mtstate->ps)->instrument, es); } /* EXPLAIN ANALYZE display of actual outcome for each tuple proposed */ @@ -4639,11 +4697,24 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors, double total; double insert_path; double other_path; + Instrumentation *local_instr; - InstrEndLoop(outerPlanState(mtstate)->instrument); + /* Progressive explain. Use auxiliary instrumentation object */ + if (es->progressive) + { + local_instr = es->pe_local_instr; + *local_instr = *outerPlanState(mtstate)->instrument; + /* Force end loop even if node is in progress */ + InstrEndLoopForce(local_instr); + } + else + { + local_instr = outerPlanState(mtstate)->instrument; + InstrEndLoop(local_instr); + } /* count the number of source rows */ - total = outerPlanState(mtstate)->instrument->ntuples; + total = local_instr->ntuples; other_path = mtstate->ps.instrument->ntuples2; insert_path = total - other_path; @@ -4663,11 +4734,24 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors, double update_path; double delete_path; double skipped_path; + Instrumentation *local_instr; - InstrEndLoop(outerPlanState(mtstate)->instrument); + /* Progressive explain. Use auxiliary instrumentation object */ + if (es->progressive) + { + local_instr = es->pe_local_instr; + *local_instr = *outerPlanState(mtstate)->instrument; + /* Force end loop even if node is in progress */ + InstrEndLoopForce(local_instr); + } + else + { + local_instr = outerPlanState(mtstate)->instrument; + InstrEndLoop(local_instr); + } /* count the number of source rows */ - total = outerPlanState(mtstate)->instrument->ntuples; + total = local_instr->ntuples; insert_path = mtstate->mt_merge_inserted; update_path = mtstate->mt_merge_updated; delete_path = mtstate->mt_merge_deleted; @@ -5922,3 +6006,393 @@ GetSerializationMetrics(DestReceiver *dest) return empty; } + +/* + * ProgressiveExplainSetup + * Adjusts QueryDesc with instrumentation for progressive explains. + * + * If progressive explain is enabled and configured to collect + * instrumentation details, we are going to adjust QueryDesc accordingly + * even if the query was not initiated with EXPLAIN ANALYZE. This + * will directly affect query execution and add computation overhead. + */ +void +ProgressiveExplainSetup(QueryDesc *queryDesc) +{ + /* Adjust instrumentation if enabled */ + if (progressive_explain == PROGRESSIVE_EXPLAIN_ANALYZE) + { + if (progressive_explain_timing) + queryDesc->instrument_options |= INSTRUMENT_TIMER; + else + queryDesc->instrument_options |= INSTRUMENT_ROWS; + if (progressive_explain_buffers) + queryDesc->instrument_options |= INSTRUMENT_BUFFERS; + if (progressive_explain_wal) + queryDesc->instrument_options |= INSTRUMENT_WAL; + } +} + +/* + * ProgressiveExplainUpdate + * Updates progressive explain for instrumented runs. + */ +void +ProgressiveExplainUpdate(PlanState *node) +{ + /* Track the current PlanState */ + node->state->query_desc->pe_es->pe_curr_node = node; + ProgressiveExplainPrint(node->state->query_desc); + node->state->query_desc->pe_es->pe_curr_node = NULL; + + /* Reset timeout flag */ + ProgressiveExplainPending = false; +} + +/* + * ProgressiveExplainFinish + * Finalizes query execution with progressive explain enabled. + */ +void +ProgressiveExplainFinish(QueryDesc *queryDesc) +{ + ProgressiveExplainCleanup(queryDesc->pe_es->pe_a); +} + +/* + * ProgressiveExplainCleanup + * Cleanup routine when progressive explain is enabled. + * + * We need deal with structures not automatically released by the memory + * context removal. Current tasks are: + * - remove local backend from progressive explain hash + * - detach from DSA used to store shared data + */ +void +ProgressiveExplainCleanup(dsa_area *a) +{ + progressiveExplainHashKey key; + + key.pid = MyProcPid; + LWLockAcquire(ExplainHashLock, LW_EXCLUSIVE); + if (a) + dsa_detach(a); + hash_search(progressiveExplainArray, &key, HASH_REMOVE, NULL); + LWLockRelease(ExplainHashLock); +} + +/* + * ProgressiveExplainBegin + * Initialization of all structures related to progressive explains. + * + * We define a ExplainState that will be reused in every iteration of + * plan prints. + * + * Progressive explain plans are printed in shared memory via DSAs. Each + * A dynamic shared memory area is created to hold the progressive plans. + * Each backend printing plans has its own DSA, which is shared with other + * backends via the global progressive explain hash through dsa_handle and + * dsa_pointer pointers. + * + * A memory context release callback is defined for manual resource release + * in case of query cancellations. + * + * A periodid timeout is configured to print the plan in fixed intervals if + * progressive explain is configured with instrumentation enabled. + */ +void +ProgressiveExplainBegin(QueryDesc *queryDesc) +{ + ExplainState *es; + progressiveExplainHashKey key; + progressiveExplainHashEntry *entry; + bool found; + + /* Configure memory context release callback */ + MemoryContextCallback *queryDescReleaseCallback; + + queryDescReleaseCallback = (MemoryContextCallback *) + palloc0(sizeof(MemoryContextCallback)); + queryDescReleaseCallback->func = ProgressiveExplainReleaseFunc; + queryDescReleaseCallback->arg = NULL; + MemoryContextRegisterResetCallback(CurrentMemoryContext, + queryDescReleaseCallback); + + /* Initialize ExplainState to be used for all prints */ + es = NewExplainState(); + queryDesc->pe_es = es; + + /* Local instrumentation object to be reused for every node */ + es->pe_local_instr = palloc0(sizeof(Instrumentation)); + + /* + * Mark ExplainState as progressive so that the plan printing function + * adjusts logic accordingly. + */ + es->progressive = true; + + es->analyze = (queryDesc->instrument_options && + (progressive_explain == PROGRESSIVE_EXPLAIN_ANALYZE)); + es->buffers = (es->analyze && progressive_explain_buffers); + es->wal = (es->analyze && progressive_explain_wal); + es->timing = (es->analyze && progressive_explain_timing); + es->summary = (es->analyze); + es->format = progressive_explain_format; + es->verbose = progressive_explain_verbose; + es->settings = progressive_explain_settings; + + /* Exclusive access is needed to update the hash */ + LWLockAcquire(ExplainHashLock, LW_EXCLUSIVE); + + /* Find or create an entry with desired hash code */ + key.pid = MyProcPid; + entry = (progressiveExplainHashEntry *) hash_search(progressiveExplainArray, + &key, + HASH_ENTER, + &found); + + /* Define the DSA and share through the hash */ + es->pe_a = dsa_create(LWTRANCHE_PROGRESSIVE_EXPLAIN_DSA); + entry->h = dsa_get_handle(es->pe_a); + entry->p = (dsa_pointer) NULL; + + LWLockRelease(ExplainHashLock); + + /* Enable timeout only if instrumentation is enabled */ + if (es->analyze) + enable_timeout_every(PROGRESSIVE_EXPLAIN_TIMEOUT, + GetCurrentTimestamp(), + progressive_explain_interval); + + /* Printing progressive plan for the first time */ + ProgressiveExplainPrint(queryDesc); +} + +/* + * ProgressiveExplainPrint + * Prints progressive explain in memory. + * + * This function resets the reusable ExplainState, prints the + * plan and updates the DSA with new data. + * + * DSA memory allocation is also done here. Amount of shared + * memory allocated depends on size of currently printed plan. + * There may be reallocations in subsequent calls if new plans + * don't fit in the existing area. + */ +void +ProgressiveExplainPrint(QueryDesc *queryDesc) +{ + bool alloc_needed = false; + + /* Produce a plan only if descriptor is being tracked */ + if (queryDesc && + queryDesc->planstate) + { + QueryDesc *currentQueryDesc = queryDesc; + + progressiveExplainHashKey key; + progressiveExplainHashEntry *entry; + progressiveExplainData *pe_data; + ExplainState *es = queryDesc->pe_es; + + /* Reset the string to be reused */ + resetStringInfo(es->str); + + /* Print the plan */ + ExplainBeginOutput(es); + ExplainPrintPlan(es, currentQueryDesc); + ExplainEndOutput(es); + + /* Exclusive access is needed to update the hash */ + key.pid = MyProcPid; + LWLockAcquire(ExplainHashLock, LW_EXCLUSIVE); + entry = (progressiveExplainHashEntry *) hash_search(progressiveExplainArray, + &key, + HASH_FIND, + NULL); + + /* Exclusive access is needed to update the hash */ + if (entry) + { + /* Plan was never printed */ + if (!entry->p) + alloc_needed = true; + else + { + pe_data = dsa_get_address(es->pe_a, + entry->p); + + /* + * Plan does not fit in existing shared memory area. + * Reallocation is needed. + */ + if (strlen(es->str->data) > + add_size(strlen(pe_data->plan), + PROGRESSIVE_EXPLAIN_ALLOC_SIZE)) + { + dsa_free(es->pe_a, entry->p); + alloc_needed = true; + } + } + + if (alloc_needed) + { + /* + * The allocated size combines the length of the currently + * printed query plan with an additional delta defined by + * PROGRESSIVE_EXPLAIN_ALLOC_SIZE. This strategy prevents + * having to reallocate the segment very often, which would be + * needed in case the length of the next printed exceeds the + * previously allocated size. + */ + entry->p = dsa_allocate(es->pe_a, + add_size(sizeof(progressiveExplainData), + add_size(strlen(es->str->data), + PROGRESSIVE_EXPLAIN_ALLOC_SIZE))); + pe_data = dsa_get_address(es->pe_a, entry->p); + pe_data->pid = MyProcPid; + strcpy(pe_data->plan, ""); + pe_data->last_print = 0; + } + + /* Update shared memory with new data */ + strcpy(pe_data->plan, es->str->data); + pe_data->last_print = GetCurrentTimestamp(); + } + + LWLockRelease(ExplainHashLock); + } +} + +/* + * ProgressiveExplainReleaseFunc + * Memory context release callback function to remove + * plan from explain hash and disable the timeout. + */ +static void +ProgressiveExplainReleaseFunc(void *arg) +{ + /* Remove row from hash */ + progressiveExplainHashKey key; + progressiveExplainHashEntry *entry; + + key.pid = MyProcPid; + LWLockAcquire(ExplainHashLock, LW_SHARED); + entry = (progressiveExplainHashEntry *) hash_search(progressiveExplainArray, + &key, + HASH_FIND, + NULL); + LWLockRelease(ExplainHashLock); + if (entry) + ProgressiveExplainCleanup(NULL); + + /* Stop timeout */ + disable_timeout(PROGRESSIVE_EXPLAIN_TIMEOUT, false); +} + +/* + * ProgressiveExplainHashShmemSize + * Compute shared memory space needed for explain hash. + */ +Size +ProgressiveExplainHashShmemSize(void) +{ + Size size = 0; + long max_table_size; + + max_table_size = add_size(MaxBackends, + max_parallel_workers); + size = add_size(size, + hash_estimate_size(max_table_size, + sizeof(progressiveExplainHashEntry))); + + return size; +} + +/* + * InitProgressiveExplainHash + * Initialize hash used to store data of progressive explains. + */ +void +InitProgressiveExplainHash(void) +{ + HASHCTL info; + + info.keysize = sizeof(progressiveExplainHashKey); + info.entrysize = sizeof(progressiveExplainHashEntry); + + progressiveExplainArray = ShmemInitHash("progressive explain hash", + 50, 50, + &info, + HASH_ELEM | HASH_BLOBS); +} + +/* + * pg_stat_progress_explain + * Return the progress of progressive explains. + */ +Datum +pg_stat_progress_explain(PG_FUNCTION_ARGS) +{ +#define EXPLAIN_ACTIVITY_COLS 3 + HASH_SEQ_STATUS hash_seq; + progressiveExplainHashEntry *entry; + dsa_area *a; + progressiveExplainData *ped; + + ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo; + + InitMaterializedSRF(fcinfo, 0); + + LWLockAcquire(ExplainHashLock, LW_SHARED); + + hash_seq_init(&hash_seq, progressiveExplainArray); + while ((entry = hash_seq_search(&hash_seq)) != NULL) + { + Datum values[EXPLAIN_ACTIVITY_COLS] = {0}; + bool nulls[EXPLAIN_ACTIVITY_COLS] = {0}; + + a = dsa_attach(entry->h); + ped = dsa_get_address(a, entry->p); + + values[0] = ped->pid; + values[1] = TimestampTzGetDatum(ped->last_print); + + if (superuser()) + values[2] = CStringGetTextDatum(ped->plan); + else + { + int num_backends = pgstat_fetch_stat_numbackends(); + int curr_backend; + + /* 1-based index */ + for (curr_backend = 1; curr_backend <= num_backends; curr_backend++) + { + LocalPgBackendStatus *local_beentry; + PgBackendStatus *beentry; + + /* Get the next one in the list */ + local_beentry = pgstat_get_local_beentry_by_index(curr_backend); + beentry = &local_beentry->backendStatus; + + if (beentry->st_procpid == ped->pid) + { + if (beentry->st_userid == GetUserId()) + values[2] = CStringGetTextDatum(ped->plan); + else + values[2] = CStringGetTextDatum(""); + break; + } + } + } + + tuplestore_putvalues(rsinfo->setResult, rsinfo->setDesc, values, nulls); + + dsa_detach(a); + + } + LWLockRelease(ExplainHashLock); + + return (Datum) 0; +} diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c index 963aa390620..b7ff473a056 100644 --- a/src/backend/executor/execMain.c +++ b/src/backend/executor/execMain.c @@ -43,6 +43,7 @@ #include "access/xact.h" #include "catalog/namespace.h" #include "catalog/partition.h" +#include "commands/explain.h" #include "commands/matview.h" #include "commands/trigger.h" #include "executor/executor.h" @@ -148,6 +149,12 @@ standard_ExecutorStart(QueryDesc *queryDesc, int eflags) /* caller must ensure the query's snapshot is active */ Assert(GetActiveSnapshot() == queryDesc->snapshot); + /* + * Setup progressive explain if enabled. + */ + if (progressive_explain != PROGRESSIVE_EXPLAIN_NONE) + ProgressiveExplainSetup(queryDesc); + /* * If the transaction is read-only, we need to check if any writes are * planned to non-temporary tables. EXPLAIN is considered read-only. @@ -173,6 +180,11 @@ standard_ExecutorStart(QueryDesc *queryDesc, int eflags) estate = CreateExecutorState(); queryDesc->estate = estate; + /* + * Adding back reference to QueryDesc + */ + estate->query_desc = queryDesc; + oldcontext = MemoryContextSwitchTo(estate->es_query_cxt); /* @@ -258,6 +270,12 @@ standard_ExecutorStart(QueryDesc *queryDesc, int eflags) */ InitPlan(queryDesc, eflags); + /* + * Start progressive explain if enabled. + */ + if (progressive_explain != PROGRESSIVE_EXPLAIN_NONE) + ProgressiveExplainBegin(queryDesc); + MemoryContextSwitchTo(oldcontext); } @@ -445,6 +463,12 @@ standard_ExecutorFinish(QueryDesc *queryDesc) MemoryContextSwitchTo(oldcontext); + /* + * Finish progressive explain if enabled. + */ + if (progressive_explain != PROGRESSIVE_EXPLAIN_NONE) + ProgressiveExplainFinish(queryDesc); + estate->es_finished = true; } diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c index f5f9cfbeead..521a7b41404 100644 --- a/src/backend/executor/execProcnode.c +++ b/src/backend/executor/execProcnode.c @@ -72,6 +72,7 @@ */ #include "postgres.h" +#include "commands/explain.h" #include "executor/executor.h" #include "executor/nodeAgg.h" #include "executor/nodeAppend.h" @@ -118,9 +119,11 @@ #include "executor/nodeWorktablescan.h" #include "miscadmin.h" #include "nodes/nodeFuncs.h" +#include "utils/guc.h" static TupleTableSlot *ExecProcNodeFirst(PlanState *node); static TupleTableSlot *ExecProcNodeInstr(PlanState *node); +static TupleTableSlot *ExecProcNodeInstrExplain(PlanState *node); static bool ExecShutdownNode_walker(PlanState *node, void *context); @@ -461,8 +464,14 @@ ExecProcNodeFirst(PlanState *node) * does instrumentation. Otherwise we can dispense with all wrappers and * have ExecProcNode() directly call the relevant function from now on. */ + if (node->instrument) - node->ExecProcNode = ExecProcNodeInstr; + { + if (progressive_explain == PROGRESSIVE_EXPLAIN_ANALYZE) + node->ExecProcNode = ExecProcNodeInstrExplain; + else + node->ExecProcNode = ExecProcNodeInstr; + } else node->ExecProcNode = node->ExecProcNodeReal; @@ -489,6 +498,31 @@ ExecProcNodeInstr(PlanState *node) return result; } +/* + * ExecProcNode wrapper that performs instrumentation calls and prints + * progressive explains. By keeping this a separate function, we add + * overhead only when progressive explain is enabled + */ +static TupleTableSlot * +ExecProcNodeInstrExplain(PlanState *node) +{ + TupleTableSlot *result; + + InstrStartNode(node->instrument); + + /* + * Update progressive after timeout is reached. + */ + if (ProgressiveExplainPending) + ProgressiveExplainUpdate(node); + + result = node->ExecProcNodeReal(node); + + InstrStopNode(node->instrument, TupIsNull(result) ? 0.0 : 1.0); + + return result; +} + /* ---------------------------------------------------------------- * MultiExecProcNode diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index 56e635f4700..6a160ee254f 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -25,6 +25,8 @@ static WalUsage save_pgWalUsage; static void BufferUsageAdd(BufferUsage *dst, const BufferUsage *add); static void WalUsageAdd(WalUsage *dst, WalUsage *add); +static void InstrEndLoopInternal(Instrumentation *instr, bool force); + /* Allocate new instrumentation structure(s) */ Instrumentation * @@ -137,7 +139,7 @@ InstrUpdateTupleCount(Instrumentation *instr, double nTuples) /* Finish a run cycle for a plan node */ void -InstrEndLoop(Instrumentation *instr) +InstrEndLoopInternal(Instrumentation *instr, bool force) { double totaltime; @@ -145,7 +147,7 @@ InstrEndLoop(Instrumentation *instr) if (!instr->running) return; - if (!INSTR_TIME_IS_ZERO(instr->starttime)) + if (!INSTR_TIME_IS_ZERO(instr->starttime) && !force) elog(ERROR, "InstrEndLoop called on running node"); /* Accumulate per-cycle statistics into totals */ @@ -164,6 +166,20 @@ InstrEndLoop(Instrumentation *instr) instr->tuplecount = 0; } +/* Safely finish a run cycle for a plan node */ +void +InstrEndLoop(Instrumentation *instr) +{ + InstrEndLoopInternal(instr, false); +} + +/* Forcibly finish a run cycle for a plan node */ +void +InstrEndLoopForce(Instrumentation *instr) +{ + InstrEndLoopInternal(instr, true); +} + /* aggregate instrumentation information */ void InstrAggNode(Instrumentation *dst, Instrumentation *add) diff --git a/src/backend/storage/ipc/ipci.c b/src/backend/storage/ipc/ipci.c index 174eed70367..15d8a3b28a8 100644 --- a/src/backend/storage/ipc/ipci.c +++ b/src/backend/storage/ipc/ipci.c @@ -25,6 +25,7 @@ #include "access/xlogprefetcher.h" #include "access/xlogrecovery.h" #include "commands/async.h" +#include "commands/explain.h" #include "miscadmin.h" #include "pgstat.h" #include "postmaster/autovacuum.h" @@ -148,6 +149,7 @@ CalculateShmemSize(int *num_semaphores) size = add_size(size, WaitEventCustomShmemSize()); size = add_size(size, InjectionPointShmemSize()); size = add_size(size, SlotSyncShmemSize()); + size = add_size(size, ProgressiveExplainHashShmemSize()); /* include additional requested shmem from preload libraries */ size = add_size(size, total_addin_request); @@ -300,6 +302,11 @@ CreateOrAttachShmemStructs(void) */ PredicateLockShmemInit(); + /* + * Set up instrumented explain hash table + */ + InitProgressiveExplainHash(); + /* * Set up process table */ diff --git a/src/backend/storage/lmgr/lwlock.c b/src/backend/storage/lmgr/lwlock.c index f1e74f184f1..1d713d942b4 100644 --- a/src/backend/storage/lmgr/lwlock.c +++ b/src/backend/storage/lmgr/lwlock.c @@ -166,6 +166,7 @@ static const char *const BuiltinTrancheNames[] = { [LWTRANCHE_SUBTRANS_SLRU] = "SubtransSLRU", [LWTRANCHE_XACT_SLRU] = "XactSLRU", [LWTRANCHE_PARALLEL_VACUUM_DSA] = "ParallelVacuumDSA", + [LWTRANCHE_PROGRESSIVE_EXPLAIN_DSA] = "ProgressiveExplainDSA", }; StaticAssertDecl(lengthof(BuiltinTrancheNames) == diff --git a/src/backend/utils/activity/wait_event_names.txt b/src/backend/utils/activity/wait_event_names.txt index e199f071628..890acf02da9 100644 --- a/src/backend/utils/activity/wait_event_names.txt +++ b/src/backend/utils/activity/wait_event_names.txt @@ -346,6 +346,7 @@ WALSummarizer "Waiting to read or update WAL summarization state." DSMRegistry "Waiting to read or update the dynamic shared memory registry." InjectionPoint "Waiting to read or update information related to injection points." SerialControl "Waiting to read or update shared pg_serial state." +ExplainHash "Waiting to access backend explain shared hash table." # # END OF PREDEFINED LWLOCKS (DO NOT CHANGE THIS LINE) diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c index 01bb6a410cb..41842b85e00 100644 --- a/src/backend/utils/init/postinit.c +++ b/src/backend/utils/init/postinit.c @@ -33,6 +33,7 @@ #include "catalog/pg_database.h" #include "catalog/pg_db_role_setting.h" #include "catalog/pg_tablespace.h" +#include "commands/explain.h" #include "libpq/auth.h" #include "libpq/libpq-be.h" #include "mb/pg_wchar.h" @@ -78,6 +79,7 @@ static void TransactionTimeoutHandler(void); static void IdleSessionTimeoutHandler(void); static void IdleStatsUpdateTimeoutHandler(void); static void ClientCheckTimeoutHandler(void); +static void ProgressiveExplainTimeoutHandler(void); static bool ThereIsAtLeastOneRole(void); static void process_startup_options(Port *port, bool am_superuser); static void process_settings(Oid databaseid, Oid roleid); @@ -741,6 +743,8 @@ InitPostgres(const char *in_dbname, Oid dboid, RegisterTimeout(CLIENT_CONNECTION_CHECK_TIMEOUT, ClientCheckTimeoutHandler); RegisterTimeout(IDLE_STATS_UPDATE_TIMEOUT, IdleStatsUpdateTimeoutHandler); + RegisterTimeout(PROGRESSIVE_EXPLAIN_TIMEOUT, + ProgressiveExplainTimeoutHandler); } /* @@ -1397,6 +1401,12 @@ ClientCheckTimeoutHandler(void) SetLatch(MyLatch); } +static void +ProgressiveExplainTimeoutHandler(void) +{ + ProgressiveExplainPending = true; +} + /* * Returns true if at least one role is defined in this database cluster. */ diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c index cce73314609..fc64eb9b9b4 100644 --- a/src/backend/utils/misc/guc_tables.c +++ b/src/backend/utils/misc/guc_tables.c @@ -40,6 +40,7 @@ #include "catalog/storage.h" #include "commands/async.h" #include "commands/event_trigger.h" +#include "commands/explain.h" #include "commands/tablespace.h" #include "commands/trigger.h" #include "commands/user.h" @@ -474,6 +475,22 @@ static const struct config_enum_entry wal_compression_options[] = { {NULL, 0, false} }; +static const struct config_enum_entry explain_format_options[] = { + {"text", EXPLAIN_FORMAT_TEXT, false}, + {"xml", EXPLAIN_FORMAT_XML, false}, + {"json", EXPLAIN_FORMAT_JSON, false}, + {"yaml", EXPLAIN_FORMAT_YAML, false}, + {NULL, 0, false} +}; + +static const struct config_enum_entry progressive_explain_options[] = { + {"off", PROGRESSIVE_EXPLAIN_NONE, false}, + {"explain", PROGRESSIVE_EXPLAIN_EXPLAIN, false}, + {"analyze", PROGRESSIVE_EXPLAIN_ANALYZE, false}, + {"false", PROGRESSIVE_EXPLAIN_NONE, true}, + {NULL, 0, false} +}; + /* * Options for enum values stored in other modules */ @@ -528,6 +545,14 @@ int log_parameter_max_length_on_error = 0; int log_temp_files = -1; double log_statement_sample_rate = 1.0; double log_xact_sample_rate = 0; +int progressive_explain = PROGRESSIVE_EXPLAIN_NONE; +bool progressive_explain_verbose = false; +bool progressive_explain_settings = false; +bool progressive_explain_timing = false; +bool progressive_explain_buffers = false; +bool progressive_explain_wal = false; +int progressive_explain_interval = 1000; +int progressive_explain_format = EXPLAIN_FORMAT_TEXT; char *backtrace_functions; int temp_file_limit = -1; @@ -2116,6 +2141,61 @@ struct config_bool ConfigureNamesBool[] = NULL, NULL, NULL }, + { + {"progressive_explain_verbose", PGC_USERSET, STATS_MONITORING, + gettext_noop("Controls whether verbose details are added to progressive explains."), + gettext_noop("Equivalent to the VERBOSE option of EXPLAIN."), + GUC_EXPLAIN + }, + &progressive_explain_verbose, + false, + NULL, NULL, NULL + }, + + { + {"progressive_explain_settings", PGC_USERSET, STATS_MONITORING, + gettext_noop("Controls whether information about modified configuration is added to progressive explains."), + gettext_noop("Equivalent to the SETTINGS option of EXPLAIN."), + GUC_EXPLAIN + }, + &progressive_explain_settings, + false, + NULL, NULL, NULL + }, + + { + {"progressive_explain_timing", PGC_USERSET, STATS_MONITORING, + gettext_noop("Controls whether information about per node timing is added to progressive explains."), + gettext_noop("Equivalent to the TIMING option of EXPLAIN."), + GUC_EXPLAIN + }, + &progressive_explain_timing, + true, + NULL, NULL, NULL + }, + + { + {"progressive_explain_buffers", PGC_USERSET, STATS_MONITORING, + gettext_noop("Controls whether information about buffers is added to progressive explains."), + gettext_noop("Equivalent to the BUFFERS option of EXPLAIN."), + GUC_EXPLAIN + }, + &progressive_explain_buffers, + false, + NULL, NULL, NULL + }, + + { + {"progressive_explain_wal", PGC_USERSET, STATS_MONITORING, + gettext_noop("Controls whether information about WAL record generation is added to progressive explains."), + gettext_noop("Equivalent to the WAL option of EXPLAIN."), + GUC_EXPLAIN + }, + &progressive_explain_wal, + false, + NULL, NULL, NULL + }, + /* End-of-list marker */ { {NULL, 0, 0, NULL, NULL}, NULL, false, NULL, NULL, NULL @@ -3771,6 +3851,18 @@ struct config_int ConfigureNamesInt[] = NULL, NULL, NULL }, + { + {"progressive_explain_interval", PGC_USERSET, STATS_MONITORING, + gettext_noop("Sets the interval between instrumented progressive " + "explains."), + NULL, + GUC_UNIT_MS + }, + &progressive_explain_interval, + 1000, 10, INT_MAX, + NULL, NULL, NULL + }, + /* End-of-list marker */ { {NULL, 0, 0, NULL, NULL}, NULL, 0, 0, 0, NULL, NULL, NULL @@ -5274,6 +5366,26 @@ struct config_enum ConfigureNamesEnum[] = NULL, NULL, NULL }, + { + {"progressive_explain_format", PGC_USERSET, STATS_MONITORING, + gettext_noop("Selects the EXPLAIN output format to be used with progressive explains."), + gettext_noop("Equivalent to the FORMAT option of EXPLAIN.") + }, + &progressive_explain_format, + EXPLAIN_FORMAT_TEXT, explain_format_options, + NULL, NULL, NULL + }, + + { + {"progressive_explain", PGC_USERSET, STATS_MONITORING, + gettext_noop("Enables progressive explains."), + gettext_noop("Explain output is visible via pg_stat_progress_explain.") + }, + &progressive_explain, + PROGRESSIVE_EXPLAIN_NONE, progressive_explain_options, + NULL, NULL, NULL + }, + /* End-of-list marker */ { {NULL, 0, 0, NULL, NULL}, NULL, 0, NULL, NULL, NULL, NULL diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index d472987ed46..a05a9cebf6f 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -651,6 +651,18 @@ #log_executor_stats = off +# - Progressive Explain - + +#progressive_explain = off +#progressive_explain_interval = 1s +#progressive_explain_format = text +#progressive_explain_settings = off +#progressive_explain_verbose = off +#progressive_explain_buffers = off +#progressive_explain_wal = off +#progressive_explain_timing = off + + #------------------------------------------------------------------------------ # VACUUMING #------------------------------------------------------------------------------ diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index 9e803d610d7..bb4e514b7ea 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -12464,4 +12464,14 @@ proargtypes => 'int4', prosrc => 'gist_stratnum_common' }, +{ oid => '8770', + descr => 'statistics: information about progress of backends running statements', + proname => 'pg_stat_progress_explain', prorows => '100', proisstrict => 'f', + proretset => 't', provolatile => 's', proparallel => 'r', + prorettype => 'record', proargtypes => 'bool', + proallargtypes => '{bool,int4,timestamptz,text}', + proargmodes => '{i,o,o,o}', + proargnames => '{mode,pid,last_print,query_plan}', + prosrc => 'pg_stat_progress_explain' }, + ] diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h index ea7419951f4..89b94dfcf67 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -13,6 +13,7 @@ #ifndef EXPLAIN_H #define EXPLAIN_H +#include "datatype/timestamp.h" #include "executor/executor.h" #include "lib/stringinfo.h" #include "parser/parse_node.h" @@ -32,6 +33,13 @@ typedef enum ExplainFormat EXPLAIN_FORMAT_YAML, } ExplainFormat; +typedef enum ProgressiveExplain +{ + PROGRESSIVE_EXPLAIN_NONE, + PROGRESSIVE_EXPLAIN_EXPLAIN, + PROGRESSIVE_EXPLAIN_ANALYZE, +} ProgressiveExplain; + typedef struct ExplainWorkersState { int num_workers; /* # of worker processes the plan used */ @@ -67,12 +75,37 @@ typedef struct ExplainState List *deparse_cxt; /* context list for deparsing expressions */ Bitmapset *printed_subplans; /* ids of SubPlans we've printed */ bool hide_workers; /* set if we find an invisible Gather */ + bool progressive; /* set if tracking a progressive explain */ int rtable_size; /* length of rtable excluding the RTE_GROUP * entry */ /* state related to the current plan node */ ExplainWorkersState *workers_state; /* needed if parallel plan */ + + /* state related to progressive explains */ + struct PlanState *pe_curr_node; + struct Instrumentation *pe_local_instr; + dsa_area *pe_a; } ExplainState; +typedef struct progressiveExplainHashKey +{ + int pid; /* PID */ +} progressiveExplainHashKey; + +typedef struct progressiveExplainHashEntry +{ + progressiveExplainHashKey key; /* hash key of entry - MUST BE FIRST */ + dsa_handle h; + dsa_pointer p; +} progressiveExplainHashEntry; + +typedef struct progressiveExplainData +{ + int pid; + TimestampTz last_print; + char plan[]; +} progressiveExplainData; + /* Hook for plugins to get control in ExplainOneQuery() */ typedef void (*ExplainOneQuery_hook_type) (Query *query, int cursorOptions, @@ -144,4 +177,13 @@ extern void ExplainCloseGroup(const char *objtype, const char *labelname, extern DestReceiver *CreateExplainSerializeDestReceiver(ExplainState *es); +extern void ProgressiveExplainBegin(QueryDesc *queryDesc); +extern void ProgressiveExplainFinish(QueryDesc *queryDesc); +extern void ProgressiveExplainSetup(QueryDesc *queryDesc); +extern void ProgressiveExplainUpdate(PlanState *node); +extern Size ProgressiveExplainHashShmemSize(void); +extern void InitProgressiveExplainHash(void); + +extern bool ProgressiveExplainPending; + #endif /* EXPLAIN_H */ diff --git a/src/include/executor/execdesc.h b/src/include/executor/execdesc.h index 86db3dc8d0d..f9985ca7429 100644 --- a/src/include/executor/execdesc.h +++ b/src/include/executor/execdesc.h @@ -47,6 +47,7 @@ typedef struct QueryDesc TupleDesc tupDesc; /* descriptor for result tuples */ EState *estate; /* executor's query-wide state */ PlanState *planstate; /* tree of per-plan-node state */ + struct ExplainState *pe_es; /* progressive explain state if enabled */ /* This field is set by ExecutePlan */ bool already_executed; /* true if previously executed */ diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h index 03653ab6c6c..21de2a5632d 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -109,6 +109,7 @@ extern void InstrStartNode(Instrumentation *instr); extern void InstrStopNode(Instrumentation *instr, double nTuples); extern void InstrUpdateTupleCount(Instrumentation *instr, double nTuples); extern void InstrEndLoop(Instrumentation *instr); +extern void InstrEndLoopForce(Instrumentation *instr); extern void InstrAggNode(Instrumentation *dst, Instrumentation *add); extern void InstrStartParallelQuery(void); extern void InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage); diff --git a/src/include/nodes/execnodes.h b/src/include/nodes/execnodes.h index 2625d7e8222..0a8ab9109ae 100644 --- a/src/include/nodes/execnodes.h +++ b/src/include/nodes/execnodes.h @@ -56,6 +56,7 @@ struct ExprState; struct ExprContext; struct RangeTblEntry; /* avoid including parsenodes.h here */ struct ExprEvalStep; /* avoid including execExpr.h everywhere */ +struct QueryDesc; /* avoid including execdesc.h here */ struct CopyMultiInsertBuffer; struct LogicalTapeSet; @@ -760,6 +761,9 @@ typedef struct EState */ List *es_insert_pending_result_relations; List *es_insert_pending_modifytables; + + /* Reference to query descriptor */ + struct QueryDesc *query_desc; } EState; diff --git a/src/include/storage/lwlock.h b/src/include/storage/lwlock.h index 2aa46fd50da..716623bde3a 100644 --- a/src/include/storage/lwlock.h +++ b/src/include/storage/lwlock.h @@ -215,6 +215,7 @@ typedef enum BuiltinTrancheIds LWTRANCHE_SUBTRANS_SLRU, LWTRANCHE_XACT_SLRU, LWTRANCHE_PARALLEL_VACUUM_DSA, + LWTRANCHE_PROGRESSIVE_EXPLAIN_DSA, LWTRANCHE_FIRST_USER_DEFINED, } BuiltinTrancheIds; diff --git a/src/include/storage/lwlocklist.h b/src/include/storage/lwlocklist.h index cf565452382..43f10a51862 100644 --- a/src/include/storage/lwlocklist.h +++ b/src/include/storage/lwlocklist.h @@ -83,3 +83,4 @@ PG_LWLOCK(49, WALSummarizer) PG_LWLOCK(50, DSMRegistry) PG_LWLOCK(51, InjectionPoint) PG_LWLOCK(52, SerialControl) +PG_LWLOCK(53, ExplainHash) diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h index 1233e07d7da..b6326550ba3 100644 --- a/src/include/utils/guc.h +++ b/src/include/utils/guc.h @@ -278,6 +278,14 @@ extern PGDLLIMPORT int log_min_duration_statement; extern PGDLLIMPORT int log_temp_files; extern PGDLLIMPORT double log_statement_sample_rate; extern PGDLLIMPORT double log_xact_sample_rate; +extern PGDLLIMPORT int progressive_explain; +extern PGDLLIMPORT int progressive_explain_interval; +extern PGDLLIMPORT int progressive_explain_format; +extern PGDLLIMPORT bool progressive_explain_verbose; +extern PGDLLIMPORT bool progressive_explain_settings; +extern PGDLLIMPORT bool progressive_explain_timing; +extern PGDLLIMPORT bool progressive_explain_buffers; +extern PGDLLIMPORT bool progressive_explain_wal; extern PGDLLIMPORT char *backtrace_functions; extern PGDLLIMPORT int temp_file_limit; diff --git a/src/include/utils/timeout.h b/src/include/utils/timeout.h index 7b19beafdc9..f2751c5b4df 100644 --- a/src/include/utils/timeout.h +++ b/src/include/utils/timeout.h @@ -36,6 +36,7 @@ typedef enum TimeoutId IDLE_STATS_UPDATE_TIMEOUT, CLIENT_CONNECTION_CHECK_TIMEOUT, STARTUP_PROGRESS_TIMEOUT, + PROGRESSIVE_EXPLAIN_TIMEOUT, /* First user-definable timeout reason */ USER_TIMEOUT, /* Maximum number of timeout reasons */ diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out index 5baba8d39ff..b93c22773be 100644 --- a/src/test/regress/expected/rules.out +++ b/src/test/regress/expected/rules.out @@ -2041,6 +2041,10 @@ pg_stat_progress_create_index| SELECT s.pid, s.param15 AS partitions_done FROM (pg_stat_get_progress_info('CREATE INDEX'::text) s(pid, datid, relid, param1, param2, param3, param4, param5, param6, param7, param8, param9, param10, param11, param12, param13, param14, param15, param16, param17, param18, param19, param20) LEFT JOIN pg_database d ON ((s.datid = d.oid))); +pg_stat_progress_explain| SELECT pid, + last_print, + query_plan + FROM pg_stat_progress_explain(true) pg_stat_progress_explain(pid, last_print, query_plan); pg_stat_progress_vacuum| SELECT s.pid, s.datid, d.datname, diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list index 80aa50d55a4..0ae80866978 100644 --- a/src/tools/pgindent/typedefs.list +++ b/src/tools/pgindent/typedefs.list @@ -2250,6 +2250,7 @@ ProcessUtilityContext ProcessUtility_hook_type ProcessingMode ProgressCommandType +ProgressiveExplain ProjectSet ProjectSetPath ProjectSetState @@ -3847,6 +3848,9 @@ process_sublinks_context proclist_head proclist_mutable_iter proclist_node +progressiveExplainData +progressiveExplainHashEntry +progressiveExplainHashKey promptStatus_t pthread_barrier_t pthread_cond_t -- 2.43.0