From 6f6849a17bf8486123081e01fb16011373c5ca76 Mon Sep 17 00:00:00 2001 From: Vladimir Rachkin Date: Wed, 13 Nov 2024 11:18:09 +0300 Subject: [PATCH] NodeSummary in EXPLAIN ANALYZE Dumps CdbExplain_NodeSummary struct in EXPLAIN ANALYZE `set gp_enable_explain_node_summary=on;` `drop table if exists tt; create table tt (a int, b int) distributed randomly;` `explain (analyze,verbose) insert into tt select * from generate_series(1,1000)a,generate_series(1,1000)b;` `explain (analyze,verbose) select * from tt where a > b;` ``` QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Gather Motion 3:1 (slice1; segments: 3) (cost=0.00..431.00 rows=1 width=8) (actual time=33.612..78.159 rows=1000 loops=1) Output: a, b Node Summary: vmax vsum vcnt imax ntuples: 1000 1000 1 -1 execmemused: 0 0 0 0 workmemused: 0 0 0 0 workmemwanted: 0 0 0 0 totalWorkfileCreated: 0 0 0 0 peakMemBalance: 44592 44592 1 -1 totalPartTableScanned: 0 0 0 0 segindex0: -1 ninst: 1 StatInsts: (segN) pstype starttime counter firsttuple startup total ntuples nloops execmemused workmemused workmemwanted workfileCreated firststart peakMemBalance numPartScanned sortMethod sortSpaceType sortSpaceUsed bnotes enotes (seg-1) 241 0.00 0.03 0.08 1000.00 1.00 0 0 0 0 0 0 44592.00 0 0 0 0 0 0 0 -> Seq Scan on public.tt (cost=0.00..431.00 rows=1 width=8) (actual time=2.512..77.640 rows=353 loops=1) Output: a, b Filter: (tt.a = 100) Node Summary: vmax vsum vcnt imax ntuples: 353 1000 3 0 execmemused: 0 0 0 0 workmemused: 0 0 0 0 workmemwanted: 0 0 0 0 totalWorkfileCreated: 0 0 0 0 peakMemBalance: 19072 57216 3 0 totalPartTableScanned: 0 0 0 0 segindex0: 0 ninst: 3 StatInsts: (segN) pstype starttime counter firsttuple startup total ntuples nloops execmemused workmemused workmemwanted workfileCreated firststart peakMemBalance numPartScanned sortMethod sortSpaceType sortSpaceUsed bnotes enotes (seg0) 211 0.00 0.00 0.08 353.00 1.00 0 0 0 0 0 0 19072.00 0 0 0 0 0 0 0 (seg1) 211 0.00 0.00 0.03 330.00 1.00 0 0 0 0 0 0 19072.00 0 0 0 0 0 0 0 (seg2) 211 0.00 0.00 0.05 317.00 1.00 0 0 0 0 0 0 19072.00 0 0 0 0 0 0 0 Planning time: 4.514 ms (slice0) Executor memory: 119K bytes. (slice1) Executor memory: 27K bytes avg x 3 workers, 27K bytes max (seg0). Memory used: 128000kB Optimizer: Pivotal Optimizer (GPORCA) Execution time: 78.584 ms (39 rows) ``` --- src/backend/cdb/cdbvars.c | 3 + src/backend/commands/explain_gp.c | 171 ++++++++++++++++++ src/backend/utils/misc/guc_gp.c | 11 ++ src/include/cdb/cdbvars.h | 6 + src/include/utils/unsync_guc_name.h | 1 + src/test/regress/expected/gp_explain.out | 44 +++++ .../regress/expected/gp_explain_optimizer.out | 44 +++++ src/test/regress/sql/gp_explain.sql | 5 + 8 files changed, 285 insertions(+) diff --git a/src/backend/cdb/cdbvars.c b/src/backend/cdb/cdbvars.c index eb78c8f11d..5623500ad0 100644 --- a/src/backend/cdb/cdbvars.c +++ b/src/backend/cdb/cdbvars.c @@ -281,6 +281,9 @@ int gp_hashagg_groups_per_bucket = 5; /* Analyzing aid */ int gp_motion_slice_noop = 0; +/* Greenplum Database EXPLAIN Feature GUCs */ +bool gp_enable_explain_node_summary = FALSE; + /* Greenplum Database Experimental Feature GUCs */ int gp_distinct_grouping_sets_threshold = 32; bool gp_enable_explain_rows_out = FALSE; diff --git a/src/backend/commands/explain_gp.c b/src/backend/commands/explain_gp.c index f6b97c38d0..5dcfbd9e0b 100644 --- a/src/backend/commands/explain_gp.c +++ b/src/backend/commands/explain_gp.c @@ -1454,6 +1454,44 @@ cdbexplain_formatSeg(char *outbuf, int bufsize, int segindex, int nInst) } /* cdbexplain_formatSeg */ +/* + * cdbexplain_formatAgg + * Convert CdbExplain_Agg to string. + * + * outbuf: [output] pointer to a char buffer to be filled + * bufsize: [input] maximum number of characters to write to outbuf (must be set by the caller) + * CdbExplain_Agg: [input] pointer to a struct CdbExplain_Agg + */ +static void +cdbexplain_formatAgg(char *outbuf, int bufsize, CdbExplain_Agg agg) +{ + Assert(outbuf != NULL && "CDBEXPLAIN: char buffer is null"); + Assert(bufsize > 0 && "CDBEXPLAIN: size of char buffer is zero"); + /* check if truncation occurs */ +#ifdef USE_ASSERT_CHECKING + int nchars_written = +#endif /* USE_ASSERT_CHECKING */ + snprintf(outbuf, bufsize, "%10.0f %10.0f %10d %10d", agg.vmax, agg.vsum, agg.vcnt, agg.imax); + + Assert(nchars_written < bufsize && + "CDBEXPLAIN: size of char buffer is smaller than the required number of chars"); +} /* cdbexplain_formatAgg */ + + +static void +ExplainPropertyAgg(const char *qlabel, CdbExplain_Agg agg, ExplainState *es) +{ + ExplainOpenGroup(qlabel, qlabel, true, es); + + ExplainPropertyFloat("vmax", agg.vmax, 0, es); + ExplainPropertyFloat("vsum", agg.vsum, 0, es); + ExplainPropertyInteger("vcnt", agg.vcnt, es); + ExplainPropertyInteger("imax", agg.imax, es); + + ExplainCloseGroup(qlabel, qlabel, true, es); +} + + /* * cdbexplain_showExecStatsBegin * Called by qDisp process to create a CdbExplain_ShowStatCtx structure @@ -1526,6 +1564,133 @@ nodeSupportWorkfileCaching(PlanState *planstate) IsA(planstate, MaterialState)); } +void +cdbexplain_NodeSummary(ExplainState *es, CdbExplain_NodeSummary *ns) { + int i; + char aggbuf[100]; + + if (es->format == EXPLAIN_FORMAT_TEXT) + { + /* + * create a header for all stats: separate each individual stat by an + * underscore, separate the grouped stats for each node by a slash + */ + appendStringInfoSpaces(es->str, es->indent * 2); + appendStringInfoString(es->str, "Node Summary: vmax vsum vcnt imax\n"); + + int ns_spaces = es->indent * 2 + 2; + + appendStringInfoSpaces(es->str, ns_spaces); + cdbexplain_formatAgg(aggbuf, sizeof(aggbuf), ns->ntuples); + appendStringInfo(es->str, "ntuples: %s\n", aggbuf); + + appendStringInfoSpaces(es->str, ns_spaces); + cdbexplain_formatAgg(aggbuf, sizeof(aggbuf), ns->execmemused); + appendStringInfo(es->str, "execmemused: %s\n", aggbuf); + + appendStringInfoSpaces(es->str, ns_spaces); + cdbexplain_formatAgg(aggbuf, sizeof(aggbuf), ns->workmemused); + appendStringInfo(es->str, "workmemused: %s\n", aggbuf); + + appendStringInfoSpaces(es->str, ns_spaces); + cdbexplain_formatAgg(aggbuf, sizeof(aggbuf), ns->workmemwanted); + appendStringInfo(es->str, "workmemwanted: %s\n", aggbuf); + + appendStringInfoSpaces(es->str, ns_spaces); + cdbexplain_formatAgg(aggbuf, sizeof(aggbuf), ns->totalWorkfileCreated); + appendStringInfo(es->str, "totalWorkfileCreated: %s\n", aggbuf); + + appendStringInfoSpaces(es->str, ns_spaces); + cdbexplain_formatAgg(aggbuf, sizeof(aggbuf), ns->peakMemBalance); + appendStringInfo(es->str, "peakMemBalance: %s\n", aggbuf); + + appendStringInfoSpaces(es->str, ns_spaces); + cdbexplain_formatAgg(aggbuf, sizeof(aggbuf), ns->totalPartTableScanned); + appendStringInfo(es->str, "totalPartTableScanned: %s\n", aggbuf); + + appendStringInfoSpaces(es->str, ns_spaces); + appendStringInfo(es->str, "segindex0: %d\n", ns->segindex0); + + appendStringInfoSpaces(es->str, ns_spaces); + appendStringInfo(es->str, "ninst: %d\n", ns->ninst); + + appendStringInfoSpaces(es->str, ns_spaces); + appendStringInfoString(es->str, "StatInsts:\n"); + appendStringInfoSpaces(es->str, ns_spaces + 2); + appendStringInfoString(es->str, "(segN) pstype starttime counter firsttuple startup total ntuples nloops execmemused workmemused workmemwanted workfileCreated firststart peakMemBalance numPartScanned sortMethod sortSpaceType sortSpaceUsed bnotes enotes\n"); + } + else { + ExplainOpenGroup("CdbExplain_NodeSummary", "CdbExplain_NodeSummary", true, es); + + ExplainPropertyAgg("ntuples", ns->ntuples, es); + ExplainPropertyAgg("execmemused", ns->execmemused, es); + ExplainPropertyAgg("workmemused", ns->workmemused, es); + ExplainPropertyAgg("workmemwanted", ns->workmemwanted, es); + ExplainPropertyAgg("totalWorkfileCreated", ns->totalWorkfileCreated, es); + ExplainPropertyAgg("peakMemBalance", ns->peakMemBalance, es); + ExplainPropertyAgg("totalPartTableScanned", ns->totalPartTableScanned, es); + + ExplainPropertyInteger("segindex0", ns->segindex0, es); + ExplainPropertyInteger("ninst", ns->ninst, es); + + ExplainOpenGroup("CdbExplain_StatInsts", "CdbExplain_StatInsts", false, es); + } + for (i = 0; i < ns->ninst; i++) + { + CdbExplain_StatInst *nsi = &ns->insts[i]; + + if (es->format == EXPLAIN_FORMAT_TEXT) + { + int nsi_spaces = es->indent * 2 + 4; + + appendStringInfoSpaces(es->str, nsi_spaces); + + appendStringInfo(es->str, "(seg%d) %d %.2f %.2f %.2f %.2f %.2f %.0f %.0f %.0f %.0f %.0f %d %.2f %.0f %d %d %d %ld %d %d\n", + ns->segindex0 + i, + nsi->pstype, + nsi->starttime.tv_sec, nsi->counter.tv_sec, nsi->firsttuple, nsi->startup, nsi->total, + nsi->ntuples, nsi->nloops, nsi->execmemused, nsi->workmemused, nsi->workmemwanted, + nsi->workfileCreated, + nsi->firststart.tv_sec, + nsi->peakMemBalance, + nsi->numPartScanned, nsi->sortMethod, nsi->sortSpaceType, + nsi->sortSpaceUsed, + nsi->bnotes, nsi->enotes); + } + else + { + ExplainOpenGroup("CdbExplain_StatInst", NULL, true, es); + ExplainPropertyInteger("Segment", ns->segindex0 + i, es); + ExplainPropertyInteger("pstype", nsi->pstype, es); + ExplainPropertyFloat("starttime", nsi->starttime.tv_sec, 2, es); + ExplainPropertyFloat("counter", nsi->counter.tv_sec, 2, es); + ExplainPropertyFloat("firsttuple", nsi->firsttuple, 2, es); + ExplainPropertyFloat("startup", nsi->startup, 2, es); + ExplainPropertyFloat("total", nsi->total, 2, es); + ExplainPropertyFloat("ntuples", nsi->ntuples, 0, es); + ExplainPropertyFloat("nloops", nsi->nloops, 0, es); + ExplainPropertyFloat("execmemused", nsi->execmemused, 0, es); + ExplainPropertyFloat("workmemused", nsi->workmemused, 0, es); + ExplainPropertyFloat("workmemwanted", nsi->workmemwanted, 0, es); + ExplainPropertyInteger("workfileCreated", nsi->workfileCreated, es); + ExplainPropertyFloat("firststart", nsi->firststart.tv_sec, 2, es); + ExplainPropertyFloat("peakMemBalance", nsi->peakMemBalance, 0, es); + ExplainPropertyInteger("numPartScanned", nsi->numPartScanned, es); + ExplainPropertyInteger("sortMethod", nsi->sortMethod, es); + ExplainPropertyInteger("sortSpaceType", nsi->sortSpaceType, es); + ExplainPropertyLong("sortSpaceUsed", nsi->sortSpaceUsed, es); + ExplainPropertyInteger("bnotes", nsi->bnotes, es); + ExplainPropertyInteger("enotes", nsi->enotes, es); + ExplainCloseGroup("CdbExplain_StatInst", NULL, true, es); + } + } + + if (es->format != EXPLAIN_FORMAT_TEXT) { + ExplainCloseGroup("CdbExplain_StatInsts", "CdbExplain_StatInsts", false, es); + ExplainCloseGroup("CdbExplain_NodeSummary", "CdbExplain_NodeSummary", true, es); + } +} /* cdbexplain_NodeSummary */ + /* * cdbexplain_showExecStats * Called by qDisp process to format a node's EXPLAIN ANALYZE statistics. @@ -1974,6 +2139,12 @@ cdbexplain_showExecStats(struct PlanState *planstate, ExplainState *es) else ExplainCloseGroup("Allstat", "Allstat", true, es); } + /* + * Dump CdbExplain_NodeSummary + */ + if (gp_enable_explain_node_summary) { + cdbexplain_NodeSummary(es, ns); + } } /* cdbexplain_showExecStats */ /* diff --git a/src/backend/utils/misc/guc_gp.c b/src/backend/utils/misc/guc_gp.c index 5dd577e26b..2f4eb4bac4 100644 --- a/src/backend/utils/misc/guc_gp.c +++ b/src/backend/utils/misc/guc_gp.c @@ -891,6 +891,17 @@ struct config_bool ConfigureNamesBool_gp[] = NULL, NULL, NULL }, + { + {"gp_enable_explain_node_summary", PGC_USERSET, CLIENT_CONN_OTHER, + gettext_noop("Dump CdbExplain_NodeSummary for every node in EXPLAIN ANALYZE."), + NULL, + GUC_NO_SHOW_ALL | GUC_NOT_IN_SAMPLE + }, + &gp_enable_explain_node_summary, + false, + NULL, NULL, NULL + }, + { {"gp_enable_sort_limit", PGC_USERSET, QUERY_TUNING_METHOD, gettext_noop("Enable LIMIT operation to be performed while sorting."), diff --git a/src/include/cdb/cdbvars.h b/src/include/cdb/cdbvars.h index 8026b44373..44406fb8e8 100644 --- a/src/include/cdb/cdbvars.h +++ b/src/include/cdb/cdbvars.h @@ -754,6 +754,12 @@ extern bool gp_enable_explain_rows_out; */ extern bool gp_enable_explain_allstat; +/* May Greenplum dump node summary from CdbExplain_NodeSummary + * during EXPLAIN ANALYZE? + * + */ +extern bool gp_enable_explain_node_summary; + /* May Greenplum restrict ORDER BY sorts to the first N rows if the ORDER BY * is wrapped by a LIMIT clause (where N=OFFSET+LIMIT)? * diff --git a/src/include/utils/unsync_guc_name.h b/src/include/utils/unsync_guc_name.h index ccbefca9c0..5da9f4363a 100644 --- a/src/include/utils/unsync_guc_name.h +++ b/src/include/utils/unsync_guc_name.h @@ -174,6 +174,7 @@ "gp_enable_exchange_default_partition", "gp_enable_explain_rows_out", "gp_enable_explain_allstat", + "gp_enable_explain_node_summary", "gp_enable_fast_sri", "gp_enable_global_deadlock_detector", "gp_enable_gpperfmon", diff --git a/src/test/regress/expected/gp_explain.out b/src/test/regress/expected/gp_explain.out index 0ab4e63722..c31fa48bf7 100644 --- a/src/test/regress/expected/gp_explain.out +++ b/src/test/regress/expected/gp_explain.out @@ -349,6 +349,50 @@ explain analyze SELECT * FROM explaintest; (8 rows) set gp_enable_explain_rows_out=DEFAULT; +-- Test explain node summary. +set gp_enable_explain_node_summary=on; +explain analyze SELECT * FROM explaintest; + QUERY PLAN +----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- + Gather Motion 3:1 (slice1; segments: 3) (cost=0.00..431.00 rows=10 width=4) (actual time=0.476..0.484 rows=10 loops=1) + Node Summary: vmax vsum vcnt imax + ntuples: 10 10 1 -1 + execmemused: 0 0 0 0 + workmemused: 0 0 0 0 + workmemwanted: 0 0 0 0 + totalWorkfileCreated: 0 0 0 0 + peakMemBalance: 5336 5336 1 -1 + totalPartTableScanned: 0 0 0 0 + segindex0: -1 + ninst: 1 + StatInsts: + (segN) pstype starttime counter firsttuple startup total ntuples nloops execmemused workmemused workmemwanted workfileCreated firststart peakMemBalance numPartScanned sortMethod sortSpaceType sortSpaceUsed bnotes enotes + (seg-1) 241 0.00 0.00 0.00 10.00 1.00 0 0 0 0 0 0 5336.00 0 0 0 0 0 0 0 + -> Seq Scan on explaintest (cost=0.00..431.00 rows=4 width=4) (actual time=0.017..0.018 rows=5 loops=1) + Node Summary: vmax vsum vcnt imax + ntuples: 5 10 3 0 + execmemused: 0 0 0 0 + workmemused: 0 0 0 0 + workmemwanted: 0 0 0 0 + totalWorkfileCreated: 0 0 0 0 + peakMemBalance: 15872 47616 3 0 + totalPartTableScanned: 0 0 0 0 + segindex0: 0 + ninst: 3 + StatInsts: + (segN) pstype starttime counter firsttuple startup total ntuples nloops execmemused workmemused workmemwanted workfileCreated firststart peakMemBalance numPartScanned sortMethod sortSpaceType sortSpaceUsed bnotes enotes + (seg0) 211 0.00 0.00 0.00 5.00 1.00 0 0 0 0 0 0 15872.00 0 0 0 0 0 0 0 + (seg1) 211 0.00 0.00 0.00 1.00 1.00 0 0 0 0 0 0 15872.00 0 0 0 0 0 0 0 + (seg2) 211 0.00 0.00 0.00 4.00 1.00 0 0 0 0 0 0 15872.00 0 0 0 0 0 0 0 + Planning time: 6.834 ms + (slice0) Executor memory: 27K bytes. + (slice1) Executor memory: 25K bytes avg x 3 workers, 25K bytes max (seg0). + Memory used: 128000kB + Optimizer: Pivotal Optimizer (GPORCA) + Execution time: 0.900 ms +(36 rows) + +set gp_enable_explain_node_summary=DEFAULT; -- -- Test output of EXPLAIN ANALYZE for Bitmap index scan's actual rows. -- diff --git a/src/test/regress/expected/gp_explain_optimizer.out b/src/test/regress/expected/gp_explain_optimizer.out index 3c45ff26f7..9c37b07db5 100644 --- a/src/test/regress/expected/gp_explain_optimizer.out +++ b/src/test/regress/expected/gp_explain_optimizer.out @@ -380,6 +380,50 @@ explain analyze SELECT * FROM explaintest; (8 rows) set gp_enable_explain_rows_out=DEFAULT; +-- Test explain node summary. +set gp_enable_explain_node_summary=on; +explain analyze SELECT * FROM explaintest; + QUERY PLAN +----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- + Gather Motion 3:1 (slice1; segments: 3) (cost=0.00..431.00 rows=10 width=4) (actual time=0.476..0.484 rows=10 loops=1) + Node Summary: vmax vsum vcnt imax + ntuples: 10 10 1 -1 + execmemused: 0 0 0 0 + workmemused: 0 0 0 0 + workmemwanted: 0 0 0 0 + totalWorkfileCreated: 0 0 0 0 + peakMemBalance: 5336 5336 1 -1 + totalPartTableScanned: 0 0 0 0 + segindex0: -1 + ninst: 1 + StatInsts: + (segN) pstype starttime counter firsttuple startup total ntuples nloops execmemused workmemused workmemwanted workfileCreated firststart peakMemBalance numPartScanned sortMethod sortSpaceType sortSpaceUsed bnotes enotes + (seg-1) 241 0.00 0.00 0.00 10.00 1.00 0 0 0 0 0 0 5336.00 0 0 0 0 0 0 0 + -> Seq Scan on explaintest (cost=0.00..431.00 rows=4 width=4) (actual time=0.017..0.018 rows=5 loops=1) + Node Summary: vmax vsum vcnt imax + ntuples: 5 10 3 0 + execmemused: 0 0 0 0 + workmemused: 0 0 0 0 + workmemwanted: 0 0 0 0 + totalWorkfileCreated: 0 0 0 0 + peakMemBalance: 15872 47616 3 0 + totalPartTableScanned: 0 0 0 0 + segindex0: 0 + ninst: 3 + StatInsts: + (segN) pstype starttime counter firsttuple startup total ntuples nloops execmemused workmemused workmemwanted workfileCreated firststart peakMemBalance numPartScanned sortMethod sortSpaceType sortSpaceUsed bnotes enotes + (seg0) 211 0.00 0.00 0.00 5.00 1.00 0 0 0 0 0 0 15872.00 0 0 0 0 0 0 0 + (seg1) 211 0.00 0.00 0.00 1.00 1.00 0 0 0 0 0 0 15872.00 0 0 0 0 0 0 0 + (seg2) 211 0.00 0.00 0.00 4.00 1.00 0 0 0 0 0 0 15872.00 0 0 0 0 0 0 0 + Planning time: 6.834 ms + (slice0) Executor memory: 27K bytes. + (slice1) Executor memory: 25K bytes avg x 3 workers, 25K bytes max (seg0). + Memory used: 128000kB + Optimizer: Pivotal Optimizer (GPORCA) + Execution time: 0.900 ms +(36 rows) + +set gp_enable_explain_node_summary=DEFAULT; -- -- Test output of EXPLAIN ANALYZE for Bitmap index scan's actual rows. -- diff --git a/src/test/regress/sql/gp_explain.sql b/src/test/regress/sql/gp_explain.sql index fecad33899..fd3d3f349d 100644 --- a/src/test/regress/sql/gp_explain.sql +++ b/src/test/regress/sql/gp_explain.sql @@ -161,6 +161,11 @@ set gp_enable_explain_rows_out=on; explain analyze SELECT * FROM explaintest; set gp_enable_explain_rows_out=DEFAULT; +-- Test explain node summary. +set gp_enable_explain_node_summary=on; +explain analyze SELECT * FROM explaintest; +set gp_enable_explain_node_summary=DEFAULT; + -- -- Test output of EXPLAIN ANALYZE for Bitmap index scan's actual rows. --