From d30e43dc227a2351aafec3492521abe4b2b1e6c7 Mon Sep 17 00:00:00 2001 From: rafaelthca Date: Tue, 7 Jan 2025 19:32:16 +0000 Subject: [PATCH v4] 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. For regular queries or queries started with EXPLAIN (without ANALYZE) the plan is printed only once at the start. For instrumented runs (started via EXPLAIN ANALYZE or when auto_explain flag log_analyze is enabled) the plan is 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_explain: timestamp when plan was last printed - explain_count: amount of times plan was printed - total_explain_time: accumulated time spent printing plans (in ms) - explain: the actual plan (limited read privileges) New GUCs: - progressive_explain: if progressive plans are printed for local session. - type: bool - default: off - context: user - progressive_explain_interval: interval between each explain print. - type: int - default: 1s - min: 10ms - context: user - progressive_explain_output_size: max output size of the plan printed in the in-memory hash table. - type: int - default: 4096 - min: 100 - context: postmaster - progressive_explain_format: format used to print the plans. - type: enum - default: text - 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 --- doc/src/sgml/config.sgml | 109 ++++ doc/src/sgml/monitoring.sgml | 84 ++++ doc/src/sgml/perform.sgml | 100 ++++ src/backend/catalog/system_views.sql | 5 + src/backend/commands/explain.c | 465 ++++++++++++++++-- src/backend/executor/execMain.c | 12 + src/backend/executor/execProcnode.c | 35 +- src/backend/executor/instrument.c | 20 +- src/backend/storage/ipc/ipci.c | 7 + .../utils/activity/wait_event_names.txt | 1 + src/backend/utils/init/postinit.c | 10 + src/backend/utils/misc/guc_tables.c | 80 +++ src/include/catalog/pg_proc.dat | 10 + src/include/commands/explain.h | 24 + src/include/executor/instrument.h | 1 + src/include/nodes/execnodes.h | 5 + src/include/storage/lwlocklist.h | 1 + src/include/utils/guc.h | 6 + src/include/utils/timeout.h | 1 + src/test/regress/expected/rules.out | 6 + 20 files changed, 930 insertions(+), 52 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index a782f10998..8fb9342a41 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -8362,6 +8362,115 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv; + + progressive_explain (boolean) + + progressive_explain configuration parameter + + + + + Determines whether progressive explains are enabled; see + . 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. + + + + + + progressive_explain_output_size (integer) + + progressive_explain_output_size configuration parameter + + + + + Specifies the amount of memory reserved to store the text of the + progressive explain for each client backend or parallel worker, for the + pg_stat_progress_explain.explain + field. If this value is specified without units, it is taken as bytes. + The default value is 4096 bytes. + This parameter can only be set at server start. + + + + + + progressive_explain_sample_rate (floating point) + + progressive_explain_sample_rate configuration parameter + + + + + Fraction of rows processed by the query until + is evaluated + to print a progressive explain plan. The default value is + 0.01, resulting in 1 check every 100 processed + rows. + + + + diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index 4e917f159a..725fcb7c69 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -6778,6 +6778,90 @@ 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_explain timestamp with time zone + + + Timestamp when plan was last printed. + + + + + + explain_count integer + + + Amount of times plan was printed. + + + + + + total_explain_time floating point + + + Accumulated time spent printing plans (in ms). + + + + + + explain text + + + The progressive explain text. By default the explain text is + truncated at 4096 bytes; this value can be changed via the + parameter . + + + + + +
+ + + diff --git a/doc/src/sgml/perform.sgml b/doc/src/sgml/perform.sgml index a502a2aaba..4f09361829 100644 --- a/doc/src/sgml/perform.sgml +++ b/doc/src/sgml/perform.sgml @@ -1109,6 +1109,106 @@ 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, or + detailed plan with row counts and accumulated run time when + EXPLAIN ANALYZE is used, can be visualized by any + session via view when + is enabled in the client + backend or parallel worker executing query. Settings + , + and + can be adjusted + to customize the printed plan, containing a length limit defined by + . + + + + For queries executed without EXPLAIN ANALYZE the + plan is printed only once at the beginning of query execution: + + + + +SET progressive_explain = on; +SET + +SELECT * +FROM test t1 +INNER JOIN test t2 ON (t1.c1 = t2.c1); + + + + +SELECT pid, explain_count, explain FROM pg_stat_progress_explain; + pid | explain_count | explain +-----+---------------+-------------------------------------------------------------------------------- + 159 | 1 | Hash Join (cost=1159375.00..3912500.00 rows=30000000 width=74) + | | Hash Cond: (t1.c1 = t2.c1) + | | -> Seq Scan on test t1 (cost=0.00..550000.00 rows=30000000 width=37) + | | -> Hash (cost=550000.00..550000.00 rows=30000000 width=37) + | | -> Seq Scan on test t2 (cost=0.00..550000.00 rows=30000000 width=37) + | | + + + + + When EXPLAIN ANALYZE is used the detailed plan is + printed progressively based on + and + settings, including + per node accumulated row count and run time statistics computed so far. This + makes progressive explain a powerful ally when investigating bottlenecks in + expensive queries without having to wait for EXPLAIN ANALYZE + to finish. + + + + 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 = on; +SET + +EXPLAIN ANALYZE SELECT * +FROM test t1 +INNER JOIN test t2 ON (t1.c1 = t2.c1); + + + + +SELECT pid, explain_count, explain FROM pg_stat_progress_explain; + pid | explain_count | explain +-----+---------------+---------------------------------------------------------------------------------------------------------------------------------------------- + 159 | 7 | Hash Join (cost=1159375.00..3912500.00 rows=30000000 width=74) (never executed) + | | Hash Cond: (t1.c1 = t2.c1) + | | -> Seq Scan on test t1 (cost=0.00..550000.00 rows=30000000 width=37) (actual time=0.009..0.009 rows=1 loops=1) + | | -> Hash (cost=550000.00..550000.00 rows=30000000 width=37) (never executed) + | | -> Seq Scan on test t2 (cost=0.00..550000.00 rows=30000000 width=37) (actual time=0.004..2165.201 rows=27925599 loops=1) (current) + | | + + + + + diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql index cddc3ea9b5..427bd883cf 100644 --- a/src/backend/catalog/system_views.sql +++ b/src/backend/catalog/system_views.sql @@ -1336,6 +1336,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 c24e66f82e..db62347939 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -13,6 +13,8 @@ */ #include "postgres.h" +#include + #include "access/xact.h" #include "catalog/pg_type.h" #include "commands/createas.h" @@ -22,6 +24,8 @@ #include "jit/jit.h" #include "libpq/pqformat.h" #include "libpq/protocol.h" +#include "miscadmin.h" +#include "funcapi.h" #include "nodes/extensible.h" #include "nodes/makefuncs.h" #include "nodes/nodeFuncs.h" @@ -40,6 +44,13 @@ #include "utils/tuplesort.h" #include "utils/typcache.h" #include "utils/xml.h" +#include "utils/backend_status.h" +#include "storage/procarray.h" +#include "executor/spi.h" +#include "utils/guc.h" +#include "utils/timeout.h" + + /* Hook for plugins to get control in ExplainOneQuery() */ @@ -48,6 +59,11 @@ 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 *explainArray = 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 +156,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 +196,8 @@ static void ExplainJSONLineEnding(ExplainState *es); static void ExplainYAMLLineStarting(ExplainState *es); static void escape_yaml(StringInfo buf, const char *str); static SerializeMetrics GetSerializationMetrics(DestReceiver *dest); +void ProgressiveExplainPrint(QueryDesc *queryDesc); +static void ExplainTrackQueryReleaseFunc(void *); @@ -392,6 +410,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 +1524,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,24 +1988,56 @@ 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. Clone instrumentation */ + if (es->progressive) + { + local_instr = palloc0(sizeof(*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) + /* Node in progress */ + if (es->progressive && planstate == planstate->state->progressive_explain_current_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 + /* Node in progress */ + if (es->progressive && planstate == planstate->state->progressive_explain_current_node) appendStringInfo(es->str, - " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)", - startup_ms, total_ms, rows, nloops); + " (actual rows=%.0f loops=%.0f) (current)", + rows, nloops); else appendStringInfo(es->str, " (actual rows=%.0f loops=%.0f)", @@ -1999,6 +2052,11 @@ 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 == planstate->state->progressive_explain_current_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) @@ -4625,7 +4683,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 */ @@ -4634,11 +4692,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. Clone instrumentation */ + if (es->progressive) + { + local_instr = palloc0(sizeof(*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; @@ -4658,11 +4729,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. Clone instrumentation */ + if (es->progressive) + { + local_instr = palloc0(sizeof(*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; @@ -5917,3 +6001,286 @@ GetSerializationMetrics(DestReceiver *dest) return empty; } + + +/* + * ProgressiveExplainPrint + * Prints progressive explain in memory. + * + * This operation needs to be done in a dedicated memory context + * as plans for instrumented runs will be printed multiple times + * and instrumentation objects need to be cloned so that stats + * can get updated without interfering with original objects. + */ +void +ProgressiveExplainPrint(QueryDesc *queryDesc) +{ + MemoryContext tmpCxt; + MemoryContext oldCxt; + instr_time starttime; + + INSTR_TIME_SET_CURRENT(starttime); + + /* Dedicated memory context for the current plan being printed */ + tmpCxt = AllocSetContextCreate(CurrentMemoryContext, + "Progressive Explain Temporary Context", + ALLOCSET_DEFAULT_SIZES); + oldCxt = MemoryContextSwitchTo(tmpCxt); + + /* Produce a plan only if descriptor is being tracked */ + if (queryDesc && + queryDesc->planstate) + { + QueryDesc *currentQueryDesc = queryDesc; + + explainHashKey key; + explainHashEntry *entry; + ExplainState *es; + + es = NewExplainState(); + + /* + * Mark ExplainState as progressive so that the plan printing function + * adjusts logic accordingly. + */ + es->progressive = true; + /* Instrumentation details come from the active QueryDesc */ + es->analyze = queryDesc->instrument_options; + es->buffers = (queryDesc->instrument_options & + INSTRUMENT_BUFFERS) != 0; + es->wal = (queryDesc->instrument_options & + INSTRUMENT_WAL) != 0; + es->timing = (queryDesc->instrument_options & + INSTRUMENT_TIMER) != 0; + es->summary = (es->analyze); + + /* Additional options come from progressive GUC settings */ + es->format = progressive_explain_format; + es->verbose = progressive_explain_verbose; + es->settings = progressive_explain_settings; + + ExplainBeginOutput(es); + ExplainPrintPlan(es, currentQueryDesc); + ExplainEndOutput(es); + + key.pid = MyProcPid; + + /* Exclusive access is needed to update the hash */ + LWLockAcquire(ExplainHashLock, LW_EXCLUSIVE); + entry = (explainHashEntry *) hash_search(explainArray, &key, HASH_FIND, NULL); + + + if (entry) + { + entry->explain_count++; + strncpy(entry->plan, es->str->data, progressive_explain_output_size); + entry->explain_duration += elapsed_time(&starttime); + entry->last_explain = GetCurrentTimestamp(); + } + + LWLockRelease(ExplainHashLock); + } + + /* Clean up temp context */ + MemoryContextSwitchTo(oldCxt); + MemoryContextDelete(tmpCxt); +} + +/* + * ProgressiveExplainBegin + * Enables progressive explain progress tracking for a query in the local backend. + * + * An progressive explain is printed at the beginning of every query if progressive_explain + * is enabled. + + * For instrumented runs started with EXPLAIN ANALYZE the progressive plan is printed + * via ExecProcNodeInstrExplain at a regular interval controlled by progressive_explain_interval. + * + * Plans are stored in shared memory object explainArray that needs to be properly + * cleared when the query finishes or gets canceled. This is achieved with the help + * of a memory context callback configured in the same memory context where the query + * descriptor was created. This strategy allows cleaning explainArray even when the + * query doesn't finish gracefully. + */ +void +ProgressiveExplainBegin(QueryDesc *queryDesc) +{ + explainHashKey key; + explainHashEntry *entry; + bool found; + + /* Configure memory context release callback */ + MemoryContextCallback *queryDescReleaseCallback; + + queryDescReleaseCallback = (MemoryContextCallback *) + palloc0(sizeof(MemoryContextCallback)); + queryDescReleaseCallback->func = ExplainTrackQueryReleaseFunc; + queryDescReleaseCallback->arg = NULL; + MemoryContextRegisterResetCallback(CurrentMemoryContext, + queryDescReleaseCallback); + + INSTR_TIME_SET_CURRENT(queryDesc->estate->progressive_explain_interval_time); + + key.pid = MyProcPid; + + /* Exclusive access is needed to update the hash */ + LWLockAcquire(ExplainHashLock, LW_EXCLUSIVE); + + /* Find or create an entry with desired hash code */ + entry = (explainHashEntry *) hash_search(explainArray, &key, HASH_ENTER, &found); + entry->pid = MyProcPid; + entry->explain_count = 0; + entry->explain_duration = 0.0f; + strcpy(entry->plan, ""); + entry->last_explain = 0; + + LWLockRelease(ExplainHashLock); + + /* Printing progressive plan for the first time */ + ProgressiveExplainPrint(queryDesc); + + /* Enable timeout for instrumented runs */ + if (queryDesc->instrument_options) + enable_timeout_every(PROGRESSIVE_EXPLAIN_TIMEOUT, GetCurrentTimestamp(), + progressive_explain_interval); +} + +/* + * ProgressiveExplainUpdate + * Updates progressive explain for instrumented runs. + */ +void +ProgressiveExplainUpdate(PlanState *node) +{ + node->state->progressive_explain_current_node = node; + ProgressiveExplainPrint(node->state->query_desc); + node->state->progressive_explain_current_node = NULL; + INSTR_TIME_SET_CURRENT(node->state->progressive_explain_interval_time); + ProgressiveExplainPending = false; +} + +/* + * ExplainTrackQueryReleaseFunc + * Memory context release callback function to remove + * plan from explain hash. + */ +static void +ExplainTrackQueryReleaseFunc(void *) +{ + /* Remove row from hash */ + explainHashKey key; + + key.pid = MyProcPid; + LWLockAcquire(ExplainHashLock, LW_EXCLUSIVE); + hash_search(explainArray, &key, HASH_REMOVE, NULL); + LWLockRelease(ExplainHashLock); + + /* Stop timeout */ + disable_timeout(PROGRESSIVE_EXPLAIN_TIMEOUT, false); +} + +/* + * ExplainHashShmemSize + * Compute shared memory space needed for explain hash. + */ +Size +ExplainHashShmemSize(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, add_size(sizeof(explainHashEntry), progressive_explain_output_size))); + + return size; +} + +/* + * InitExplainHash + * Initialize hash used to store data of progressive explains. + */ +void +InitExplainHash(void) +{ + HASHCTL info; + + info.keysize = sizeof(explainHashKey); + info.entrysize = sizeof(explainHashEntry) + progressive_explain_output_size; + + explainArray = ShmemInitHash("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) +{ + char duration[1024]; +#define EXPLAIN_ACTIVITY_COLS 5 + HASH_SEQ_STATUS hash_seq; + explainHashEntry *entry; + + ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo; + + InitMaterializedSRF(fcinfo, 0); + + LWLockAcquire(ExplainHashLock, LW_SHARED); + + hash_seq_init(&hash_seq, explainArray); + while ((entry = hash_seq_search(&hash_seq)) != NULL) + { + Datum values[EXPLAIN_ACTIVITY_COLS] = {0}; + bool nulls[EXPLAIN_ACTIVITY_COLS] = {0}; + + values[0] = entry->pid; + values[1] = TimestampTzGetDatum(entry->last_explain); + values[2] = entry->explain_count; + sprintf(duration, "%.3f", 1000.0 * entry->explain_duration); + values[3] = CStringGetTextDatum(duration); + + if (superuser()) + values[4] = CStringGetTextDatum(entry->plan); + else + { + int num_backends = pgstat_fetch_stat_numbackends(); + int curr_backend; + bool found; + + /* 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 == entry->pid) + { + found = true; + if (beentry->st_userid == GetUserId()) + values[4] = CStringGetTextDatum(entry->plan); + else + values[4] = CStringGetTextDatum(""); + break; + } + } + + if (!found) + values[3] = CStringGetTextDatum(""); + } + + tuplestore_putvalues(rsinfo->setResult, rsinfo->setDesc, values, nulls); + + } + LWLockRelease(ExplainHashLock); + + return (Datum) 0; +} diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c index fb8dba3ab2..83fcdf15a6 100644 --- a/src/backend/executor/execMain.c +++ b/src/backend/executor/execMain.c @@ -61,6 +61,7 @@ #include "utils/partcache.h" #include "utils/rls.h" #include "utils/snapmgr.h" +#include "commands/explain.h" /* Hooks for plugins to get control in ExecutorStart/Run/Finish/End */ @@ -172,6 +173,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 +264,12 @@ standard_ExecutorStart(QueryDesc *queryDesc, int eflags) InitPlan(queryDesc, eflags); MemoryContextSwitchTo(oldcontext); + + /* + * Start progressive explain if enabled. + */ + if (progressive_explain) + ProgressiveExplainBegin(queryDesc); } /* ---------------------------------------------------------------- diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c index f5f9cfbeea..952aa1ba87 100644 --- a/src/backend/executor/execProcnode.c +++ b/src/backend/executor/execProcnode.c @@ -118,9 +118,13 @@ #include "executor/nodeWorktablescan.h" #include "miscadmin.h" #include "nodes/nodeFuncs.h" +#include "commands/explain.h" +#include "utils/guc.h" +#include "common/pg_prng.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 +465,12 @@ 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) + node->ExecProcNode = ExecProcNodeInstrExplain; + else + node->ExecProcNode = ExecProcNodeInstr; else node->ExecProcNode = node->ExecProcNodeReal; @@ -489,6 +497,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 2d3569b374..ac17c7e9d8 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 174eed7036..efb4af1971 100644 --- a/src/backend/storage/ipc/ipci.c +++ b/src/backend/storage/ipc/ipci.c @@ -50,6 +50,7 @@ #include "storage/sinvaladt.h" #include "utils/guc.h" #include "utils/injection_point.h" +#include "commands/explain.h" /* GUCs */ int shared_memory_type = DEFAULT_SHARED_MEMORY_TYPE; @@ -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, ExplainHashShmemSize()); /* 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 + */ + InitExplainHash(); + /* * Set up process table */ diff --git a/src/backend/utils/activity/wait_event_names.txt b/src/backend/utils/activity/wait_event_names.txt index e199f07162..890acf02da 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 01bb6a410c..1e1fd2460a 100644 --- a/src/backend/utils/init/postinit.c +++ b/src/backend/utils/init/postinit.c @@ -65,6 +65,7 @@ #include "utils/snapmgr.h" #include "utils/syscache.h" #include "utils/timeout.h" +#include "commands/explain.h" static HeapTuple GetDatabaseTuple(const char *dbname); static HeapTuple GetDatabaseTupleByOid(Oid dboid); @@ -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 38cb9e970d..706e15cca1 100644 --- a/src/backend/utils/misc/guc_tables.c +++ b/src/backend/utils/misc/guc_tables.c @@ -46,6 +46,7 @@ #include "commands/vacuum.h" #include "common/file_utils.h" #include "common/scram-common.h" +#include "commands/explain.h" #include "jit/jit.h" #include "libpq/auth.h" #include "libpq/libpq.h" @@ -474,6 +475,14 @@ 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} +}; + /* * Options for enum values stored in other modules */ @@ -528,6 +537,12 @@ 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; +bool progressive_explain = false; +bool progressive_explain_verbose = false; +bool progressive_explain_settings = false; +int progressive_explain_interval = 1000; +int progressive_explain_format = EXPLAIN_FORMAT_TEXT; +int progressive_explain_output_size = 4096; char *backtrace_functions; int temp_file_limit = -1; @@ -2096,6 +2111,39 @@ struct config_bool ConfigureNamesBool[] = 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."), + GUC_EXPLAIN + }, + &progressive_explain, + false, + 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 + }, + /* End-of-list marker */ { {NULL, 0, 0, NULL, NULL}, NULL, false, NULL, NULL, NULL @@ -3743,6 +3791,28 @@ 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 + }, + + { + {"progressive_explain_output_size", PGC_POSTMASTER, STATS_MONITORING, + gettext_noop("Sets the size reserved for pg_stat_progress_explain.explain, in bytes."), + NULL + }, + &progressive_explain_output_size, + 4096, 100, 1048576, + NULL, NULL, NULL + }, + /* End-of-list marker */ { {NULL, 0, 0, NULL, NULL}, NULL, 0, 0, 0, NULL, NULL, NULL @@ -5236,6 +5306,16 @@ 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 + }, + /* End-of-list marker */ { {NULL, 0, 0, NULL, NULL}, NULL, 0, NULL, NULL, NULL, NULL diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index 5b8c2ad2a5..534bdcaca3 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -12454,4 +12454,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,int4,text,text}', + proargmodes => '{i,o,o,o,o,o}', + proargnames => '{mode,pid,last_explain,explain_count,total_explain_time,explain}', + prosrc => 'pg_stat_progress_explain' }, + ] diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h index ea7419951f..cdcdac9f8d 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -16,6 +16,7 @@ #include "executor/executor.h" #include "lib/stringinfo.h" #include "parser/parse_node.h" +#include "datatype/timestamp.h" typedef enum ExplainSerializeOption { @@ -67,12 +68,28 @@ 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 */ } ExplainState; +typedef struct explainHashKey +{ + int pid; /* PID */ +} explainHashKey; + +typedef struct explainHashEntry +{ + explainHashKey key; /* hash key of entry - MUST BE FIRST */ + int pid; + TimestampTz last_explain; + int explain_count; + float explain_duration; + char plan[]; +} explainHashEntry; + /* Hook for plugins to get control in ExplainOneQuery() */ typedef void (*ExplainOneQuery_hook_type) (Query *query, int cursorOptions, @@ -144,4 +161,11 @@ extern void ExplainCloseGroup(const char *objtype, const char *labelname, extern DestReceiver *CreateExplainSerializeDestReceiver(ExplainState *es); +extern void ProgressiveExplainBegin(QueryDesc *queryDesc); +extern void ProgressiveExplainUpdate(PlanState *node); +extern Size ExplainHashShmemSize(void); +extern void InitExplainHash(void); + +extern bool ProgressiveExplainPending; + #endif /* EXPLAIN_H */ diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h index 5a6eff75c6..d431877efe 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -108,6 +108,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 d0f2dca592..3225e67023 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; @@ -751,6 +752,10 @@ typedef struct EState */ List *es_insert_pending_result_relations; List *es_insert_pending_modifytables; + + struct QueryDesc *query_desc; + instr_time progressive_explain_interval_time; + struct PlanState *progressive_explain_current_node; } EState; diff --git a/src/include/storage/lwlocklist.h b/src/include/storage/lwlocklist.h index cf56545238..43f10a5186 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 532d6642bb..3a4b1f2da5 100644 --- a/src/include/utils/guc.h +++ b/src/include/utils/guc.h @@ -274,6 +274,12 @@ 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 bool progressive_explain; +extern PGDLLIMPORT bool progressive_explain_verbose; +extern PGDLLIMPORT bool progressive_explain_settings; +extern PGDLLIMPORT int progressive_explain_interval; +extern PGDLLIMPORT int progressive_explain_output_size; +extern PGDLLIMPORT int progressive_explain_format; 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 7b19beafdc..f2751c5b4d 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 3361f6a69c..0552017506 100644 --- a/src/test/regress/expected/rules.out +++ b/src/test/regress/expected/rules.out @@ -2040,6 +2040,12 @@ 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_explain, + explain_count, + total_explain_time, + explain + FROM pg_stat_progress_explain(true) pg_stat_progress_explain(pid, last_explain, explain_count, total_explain_time, explain); pg_stat_progress_vacuum| SELECT s.pid, s.datid, d.datname, -- 2.34.1