Great, thank you. I noticed in the CF patch tester app, the build fails on Windows [1]. Investigating, I realized I had failed to fully strip volatile EXPLAIN info (namely buffers) in TEXT mode due to a bad regexp_replace. I've fixed this in the attached patch (which I also rebased against current master again).
[1]: https://ci.appveyor.com/project/postgresql-cfbot/postgresql/build/1.0.76313
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index d189b8d573..b4108f82ec 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -100,7 +100,7 @@ static void show_sortorder_options(StringInfo buf, Node *sortexpr, Oid sortOperator, Oid collation, bool nullsFirst); static void show_tablesample(TableSampleClause *tsc, PlanState *planstate, List *ancestors, ExplainState *es); -static void show_sort_info(SortState *sortstate, ExplainState *es); +static void show_sort_info(SortState *sortstate, StringInfo* worker_strs, ExplainState *es); static void show_hash_info(HashState *hashstate, ExplainState *es); static void show_tidbitmap_info(BitmapHeapScanState *planstate, ExplainState *es); @@ -131,7 +131,9 @@ static void ExplainXMLTag(const char *tagname, int flags, ExplainState *es); static void ExplainJSONLineEnding(ExplainState *es); static void ExplainYAMLLineStarting(ExplainState *es); static void escape_yaml(StringInfo buf, const char *str); - +static void ExplainOpenWorker(StringInfo worker_str, ExplainState *es); +static void ExplainCloseWorker(ExplainState *es); +static void ExplainFlushWorkers(StringInfo *worker_strs, int num_workers, ExplainState *es); /* @@ -289,6 +291,7 @@ NewExplainState(void) es->costs = true; /* Prepare output buffer. */ es->str = makeStringInfo(); + es->root_str = es->str; return es; } @@ -1090,9 +1093,19 @@ ExplainNode(PlanState *planstate, List *ancestors, const char *partialmode = NULL; const char *operation = NULL; const char *custom_name = NULL; + StringInfo *worker_strs = NULL; int save_indent = es->indent; bool haschildren; + /* Prepare per-worker output */ + if (es->analyze && planstate->worker_instrument) + { + int num_workers = planstate->worker_instrument->num_workers; + worker_strs = (StringInfo *) palloc0(num_workers * sizeof(StringInfo)); + for (int n = 0; n < num_workers; n++) + worker_strs[n] = makeStringInfo(); + } + switch (nodeTag(plan)) { case T_Result: @@ -1357,6 +1370,55 @@ ExplainNode(PlanState *planstate, List *ancestors, ExplainPropertyBool("Parallel Aware", plan->parallel_aware, es); } + /* Prepare worker general execution details */ + if (es->analyze && es->verbose && !es->hide_workers && planstate->worker_instrument) + { + WorkerInstrumentation *w = planstate->worker_instrument; + + for (int n = 0; n < w->num_workers; ++n) + { + Instrumentation *instrument = &w->instrument[n]; + double nloops = instrument->nloops; + double startup_ms; + double total_ms; + double rows; + + if (nloops <= 0) + continue; + startup_ms = 1000.0 * instrument->startup / nloops; + total_ms = 1000.0 * instrument->total / nloops; + rows = instrument->ntuples / nloops; + + ExplainOpenWorker(worker_strs[n], es); + + if (es->format == EXPLAIN_FORMAT_TEXT) + { + if (es->timing) + appendStringInfo(es->str, + "actual time=%.3f..%.3f rows=%.0f loops=%.0f\n", + startup_ms, total_ms, rows, nloops); + else + appendStringInfo(es->str, + "actual rows=%.0f loops=%.0f\n", + rows, nloops); + } + else + { + if (es->timing) + { + ExplainPropertyFloat("Actual Startup Time", "ms", + startup_ms, 3, es); + ExplainPropertyFloat("Actual Total Time", "ms", + total_ms, 3, es); + } + ExplainPropertyFloat("Actual Rows", NULL, rows, 0, es); + ExplainPropertyFloat("Actual Loops", NULL, nloops, 0, es); + } + } + + ExplainCloseWorker(es); + } + switch (nodeTag(plan)) { case T_SeqScan: @@ -1856,7 +1918,7 @@ ExplainNode(PlanState *planstate, List *ancestors, break; case T_Sort: show_sort_keys(castNode(SortState, planstate), ancestors, es); - show_sort_info(castNode(SortState, planstate), es); + show_sort_info(castNode(SortState, planstate), worker_strs, es); break; case T_MergeAppend: show_merge_append_keys(castNode(MergeAppendState, planstate), @@ -1885,76 +1947,31 @@ ExplainNode(PlanState *planstate, List *ancestors, if (es->buffers && planstate->instrument) show_buffer_usage(es, &planstate->instrument->bufusage); - /* Show worker detail */ - if (es->analyze && es->verbose && !es->hide_workers && - planstate->worker_instrument) + /* Prepare worker buffer usage */ + if (es->buffers && es->analyze && es->verbose && !es->hide_workers + && planstate->worker_instrument) { WorkerInstrumentation *w = planstate->worker_instrument; - bool opened_group = false; int n; for (n = 0; n < w->num_workers; ++n) { Instrumentation *instrument = &w->instrument[n]; double nloops = instrument->nloops; - double startup_ms; - double total_ms; - double rows; if (nloops <= 0) continue; - startup_ms = 1000.0 * instrument->startup / nloops; - total_ms = 1000.0 * instrument->total / nloops; - rows = instrument->ntuples / nloops; - if (es->format == EXPLAIN_FORMAT_TEXT) - { - appendStringInfoSpaces(es->str, es->indent * 2); - appendStringInfo(es->str, "Worker %d: ", n); - if (es->timing) - appendStringInfo(es->str, - "actual time=%.3f..%.3f rows=%.0f loops=%.0f\n", - startup_ms, total_ms, rows, nloops); - else - appendStringInfo(es->str, - "actual rows=%.0f loops=%.0f\n", - rows, nloops); - es->indent++; - if (es->buffers) - show_buffer_usage(es, &instrument->bufusage); - es->indent--; - } - else - { - if (!opened_group) - { - ExplainOpenGroup("Workers", "Workers", false, es); - opened_group = true; - } - ExplainOpenGroup("Worker", NULL, true, es); - ExplainPropertyInteger("Worker Number", NULL, n, es); - - if (es->timing) - { - ExplainPropertyFloat("Actual Startup Time", "ms", - startup_ms, 3, es); - ExplainPropertyFloat("Actual Total Time", "ms", - total_ms, 3, es); - } - ExplainPropertyFloat("Actual Rows", NULL, rows, 0, es); - ExplainPropertyFloat("Actual Loops", NULL, nloops, 0, es); - - if (es->buffers) - show_buffer_usage(es, &instrument->bufusage); - - ExplainCloseGroup("Worker", NULL, true, es); - } + ExplainOpenWorker(worker_strs[n], es); + show_buffer_usage(es, &instrument->bufusage); } - - if (opened_group) - ExplainCloseGroup("Workers", "Workers", false, es); + ExplainCloseWorker(es); } + /* Show worker detail */ + if (planstate->worker_instrument) + ExplainFlushWorkers(worker_strs, planstate->worker_instrument->num_workers, es); + /* Get ready to display the child plans */ haschildren = planstate->initPlan || outerPlanState(planstate) || @@ -2552,7 +2569,7 @@ show_tablesample(TableSampleClause *tsc, PlanState *planstate, * If it's EXPLAIN ANALYZE, show tuplesort stats for a sort node */ static void -show_sort_info(SortState *sortstate, ExplainState *es) +show_sort_info(SortState *sortstate, StringInfo *worker_strs, ExplainState *es) { if (!es->analyze) return; @@ -2593,7 +2610,7 @@ show_sort_info(SortState *sortstate, ExplainState *es) if (sortstate->shared_info != NULL) { int n; - bool opened_group = false; + bool indent = es->has_worker_output; for (n = 0; n < sortstate->shared_info->num_workers; n++) { @@ -2609,32 +2626,24 @@ show_sort_info(SortState *sortstate, ExplainState *es) spaceType = tuplesort_space_type_name(sinstrument->spaceType); spaceUsed = sinstrument->spaceUsed; + ExplainOpenWorker(worker_strs[n], es); + if (es->format == EXPLAIN_FORMAT_TEXT) { - appendStringInfoSpaces(es->str, es->indent * 2); - if (n > 0 || !es->hide_workers) - appendStringInfo(es->str, "Worker %d: ", n); + if (indent) + appendStringInfoSpaces(es->str, es->indent * 2); appendStringInfo(es->str, "Sort Method: %s %s: %ldkB\n", sortMethod, spaceType, spaceUsed); } else { - if (!opened_group) - { - ExplainOpenGroup("Workers", "Workers", false, es); - opened_group = true; - } - ExplainOpenGroup("Worker", NULL, true, es); - ExplainPropertyInteger("Worker Number", NULL, n, es); ExplainPropertyText("Sort Method", sortMethod, es); ExplainPropertyInteger("Sort Space Used", "kB", spaceUsed, es); ExplainPropertyText("Sort Space Type", spaceType, es); - ExplainCloseGroup("Worker", NULL, true, es); } } - if (opened_group) - ExplainCloseGroup("Workers", "Workers", false, es); + ExplainCloseWorker(es); } } @@ -3751,6 +3760,68 @@ ExplainCloseGroup(const char *objtype, const char *labelname, } } +/* + * Begin output for a specific worker. If we are currently producing output + * for another worker, close that worker automatically. + */ +static void +ExplainOpenWorker(StringInfo worker_str, ExplainState *es) +{ + /* + * For structured formats, we indent twice: once for the "Worker" group + * itself and once for the surrounding "Workers" group. For text format, + * we just indent once, to add worker info on the next worker line. Either + * way, we only need to adjust indentation once for each string of + * ExplainOpenWorker calls. + */ + if (es->str == es->root_str) + es->indent += es->format == EXPLAIN_FORMAT_TEXT ? 1 : 2; + + es->has_worker_output = true; + es->str = worker_str; +} + +/* + * Explicitly end output for the current worker and resume output + * for the root of the node. + */ +static void +ExplainCloseWorker(ExplainState *es) +{ + /* as above, the text format has different indentation */ + es->indent -= es->format == EXPLAIN_FORMAT_TEXT ? 1 : 2; + + es->str = es->root_str; +} + +/* + * Flush worker output for this node and reset the worker output state. + */ +static void +ExplainFlushWorkers(StringInfo* worker_strs, int num_workers, ExplainState *es) +{ + if (!es->has_worker_output) + return; + + ExplainOpenGroup("Workers", "Workers", false, es); + for (int i = 0; i < num_workers; i++) + { + ExplainOpenGroup("Worker", NULL, true, es); + if (es->format == EXPLAIN_FORMAT_TEXT) + { + appendStringInfoSpaces(es->str, es->indent * 2); + appendStringInfo(es->str, "Worker %d: ", i); + } + else + ExplainPropertyInteger("Worker Number", NULL, i, es); + + appendStringInfoString(es->str, worker_strs[i]->data); + ExplainCloseGroup("Worker", NULL, true, es); + } + ExplainCloseGroup("Workers", "Workers", false, es); + es->has_worker_output = false; +} + /* * Emit a "dummy" group that never has any members. * diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h index 45027a7c47..1f9208b571 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -27,7 +27,7 @@ typedef enum ExplainFormat typedef struct ExplainState { - StringInfo str; /* output buffer */ + StringInfo str; /* current output buffer */ /* options */ bool verbose; /* be verbose */ bool analyze; /* print actual times */ @@ -40,6 +40,8 @@ typedef struct ExplainState /* state for output formatting --- not reset for each new plan tree */ int indent; /* current indentation level */ List *grouping_stack; /* format-specific grouping state */ + bool has_worker_output; /* whether current node has worker metadata */ + StringInfo root_str; /* root output buffer */ /* state related to the current plan tree (filled by ExplainPrintPlan) */ PlannedStmt *pstmt; /* top of plan */ List *rtable; /* range table */ diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out new file mode 100644 index 0000000000..12ea1f0e5b --- /dev/null +++ b/src/test/regress/expected/explain.out @@ -0,0 +1,114 @@ +-- +-- EXPLAIN +-- +-- helper functions for examining explain output +-- return a json explain of given query +CREATE OR REPLACE FUNCTION json_explain(query text, variadic opts text[]) + RETURNS json LANGUAGE PLPGSQL AS $$ +DECLARE + plan json; +BEGIN + EXECUTE 'EXPLAIN (' || array_to_string(array_append(opts, 'FORMAT JSON) '), ', ') || query INTO STRICT plan; + RETURN plan; +END; +$$; +-- return a text explain of given query +CREATE OR REPLACE FUNCTION text_explain(query text, variadic opts text[]) + RETURNS text LANGUAGE PLPGSQL AS $$ +DECLARE + plan_row RECORD; + plan text = ''; +BEGIN + FOR plan_row IN EXECUTE 'EXPLAIN (' || array_to_string(array_append(opts, 'FORMAT TEXT) '), ', ') || query LOOP + plan = plan || plan_row."QUERY PLAN" || E'\n'; + END LOOP; + + RETURN plan; +END; +$$; +/* + * Takes a json object and processes its keys and values. For every + * matching key whose value is a number, set it to zero to facilitate + * comparisons for values that can vary across executions. If not a number, + * set the value to -1 to indicate we matched an unexpected key. Return + * non-matching keys and values unmodified. + */ +CREATE OR REPLACE FUNCTION json_normalize_numeric_keys_matching(obj json, regexp text) + RETURNS json LANGUAGE SQL AS $$ +SELECT + coalesce(json_object_agg( + key, + CASE + WHEN key ~ regexp THEN + CASE json_typeof(value) + WHEN 'number' THEN 0::text::json + ELSE (-1)::text::json + END + ELSE value + END + ), '{}') +FROM + json_each(obj) +$$; +-- explain only worker information, normalizing any values that could vary across executions +CREATE OR REPLACE FUNCTION explain_workers(plan_node json) + RETURNS json LANGUAGE SQL AS $$ +SELECT + coalesce(json_object_agg(key, value), '{}') +FROM ( + SELECT + key, + CASE key + WHEN 'Workers' THEN + (SELECT json_agg( + json_normalize_numeric_keys_matching(worker, '(Blocks|Time)$|Sort Space Used') + ) + FROM json_array_elements(value) AS workers(worker)) + WHEN 'Plans' THEN + (SELECT json_agg( + explain_workers(child) + ) + FROM json_array_elements(value) AS children(child)) + END AS value + FROM + json_each(plan_node) AS entries(key, value) + WHERE + key IN ('Workers', 'Plans') +) AS plan_fields(key, value); +$$; +-- test that per-worker sort and buffers output is combined correctly in EXPLAIN +set force_parallel_mode = true; +SELECT explain_workers(json_explain($$ + SELECT * FROM (VALUES(1),(2)) x ORDER BY x; +$$, 'verbose', 'analyze', 'buffers') -> 0 -> 'Plan'); + explain_workers +-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- + { "Plans" : [{ "Workers" : [{ "Worker Number" : 0, "Actual Startup Time" : 0, "Actual Total Time" : 0, "Actual Rows" : 2, "Actual Loops" : 1, "Sort Method" : "quicksort", "Sort Space Used" : 0, "Sort Space Type" : "Memory", "Shared Hit Blocks" : 0, "Shared Read Blocks" : 0, "Shared Dirtied Blocks" : 0, "Shared Written Blocks" : 0, "Local Hit Blocks" : 0, "Local Read Blocks" : 0, "Local Dirtied Blocks" : 0, "Local Written Blocks" : 0, "Temp Read Blocks" : 0, "Temp Written Blocks" : 0 }], "Plans" : [{ "Workers" : [{ "Worker Number" : 0, "Actual Startup Time" : 0, "Actual Total Time" : 0, "Actual Rows" : 2, "Actual Loops" : 1, "Shared Hit Blocks" : 0, "Shared Read Blocks" : 0, "Shared Dirtied Blocks" : 0, "Shared Written Blocks" : 0, "Local Hit Blocks" : 0, "Local Read Blocks" : 0, "Local Dirtied Blocks" : 0, "Local Written Blocks" : 0, "Temp Read Blocks" : 0, "Temp Written Blocks" : 0 }] }] }] } +(1 row) + +SELECT regexp_replace(regexp_replace(text_explain($$ + SELECT * FROM (VALUES(1),(2)) x ORDER BY x; +$$, 'verbose', 'analyze', 'buffers', 'timing off', 'costs off', 'summary off'), + 'Buffers:.+$', 'Buffers: xxx', 'ng'), 'Sort Method:.+$', 'Sort Method: xxx', 'ng'); + regexp_replace +------------------------------------------------------------------- + Gather (actual rows=2 loops=1) + + Output: "*VALUES*".column1, (ROW("*VALUES*".column1)) + + Workers Planned: 1 + + Workers Launched: 1 + + Single Copy: true + + Buffers: xxx + + -> Sort (actual rows=2 loops=1) + + Output: "*VALUES*".column1, (ROW("*VALUES*".column1)) + + Sort Key: (ROW("*VALUES*".column1)) + + Buffers: xxx + + Worker 0: actual rows=2 loops=1 + + Sort Method: xxx + + Buffers: xxx + + -> Values Scan on "*VALUES*" (actual rows=2 loops=1) + + Output: "*VALUES*".column1, ROW("*VALUES*".column1)+ + Worker 0: actual rows=2 loops=1 + + +(1 row) + +reset force_parallel_mode; diff --git a/src/test/regress/expected/select_parallel.out b/src/test/regress/expected/select_parallel.out index 96dfb7c8dd..cba15f7133 100644 --- a/src/test/regress/expected/select_parallel.out +++ b/src/test/regress/expected/select_parallel.out @@ -591,10 +591,10 @@ select * from explain_parallel_sort_stats(); -> Sort (actual rows=2000 loops=15) Sort Key: tenk1.ten Sort Method: quicksort Memory: xxx - Worker 0: Sort Method: quicksort Memory: xxx - Worker 1: Sort Method: quicksort Memory: xxx - Worker 2: Sort Method: quicksort Memory: xxx - Worker 3: Sort Method: quicksort Memory: xxx + Worker 0: Sort Method: quicksort Memory: xxx + Worker 1: Sort Method: quicksort Memory: xxx + Worker 2: Sort Method: quicksort Memory: xxx + Worker 3: Sort Method: quicksort Memory: xxx -> Parallel Seq Scan on tenk1 (actual rows=2000 loops=15) Filter: (ten < 100) (14 rows) diff --git a/src/test/regress/parallel_schedule b/src/test/regress/parallel_schedule index d33a4e143d..d2b17dd3ea 100644 --- a/src/test/regress/parallel_schedule +++ b/src/test/regress/parallel_schedule @@ -112,7 +112,7 @@ test: plancache limit plpgsql copy2 temp domain rangefuncs prepare conversion tr # ---------- # Another group of parallel tests # ---------- -test: partition_join partition_prune reloptions hash_part indexing partition_aggregate partition_info tuplesort +test: partition_join partition_prune reloptions hash_part indexing partition_aggregate partition_info tuplesort explain # event triggers cannot run concurrently with any test that runs DDL test: event_trigger diff --git a/src/test/regress/serial_schedule b/src/test/regress/serial_schedule index f86f5c5682..acba391332 100644 --- a/src/test/regress/serial_schedule +++ b/src/test/regress/serial_schedule @@ -193,6 +193,7 @@ test: indexing test: partition_aggregate test: partition_info test: tuplesort +test: explain test: event_trigger test: fast_default test: stats diff --git a/src/test/regress/sql/explain.sql b/src/test/regress/sql/explain.sql new file mode 100644 index 0000000000..af443000da --- /dev/null +++ b/src/test/regress/sql/explain.sql @@ -0,0 +1,98 @@ +-- +-- EXPLAIN +-- + +-- helper functions for examining explain output + +-- return a json explain of given query +CREATE OR REPLACE FUNCTION json_explain(query text, variadic opts text[]) + RETURNS json LANGUAGE PLPGSQL AS $$ +DECLARE + plan json; +BEGIN + EXECUTE 'EXPLAIN (' || array_to_string(array_append(opts, 'FORMAT JSON) '), ', ') || query INTO STRICT plan; + RETURN plan; +END; +$$; + +-- return a text explain of given query +CREATE OR REPLACE FUNCTION text_explain(query text, variadic opts text[]) + RETURNS text LANGUAGE PLPGSQL AS $$ +DECLARE + plan_row RECORD; + plan text = ''; +BEGIN + FOR plan_row IN EXECUTE 'EXPLAIN (' || array_to_string(array_append(opts, 'FORMAT TEXT) '), ', ') || query LOOP + plan = plan || plan_row."QUERY PLAN" || E'\n'; + END LOOP; + + RETURN plan; +END; +$$; + + +/* + * Takes a json object and processes its keys and values. For every + * matching key whose value is a number, set it to zero to facilitate + * comparisons for values that can vary across executions. If not a number, + * set the value to -1 to indicate we matched an unexpected key. Return + * non-matching keys and values unmodified. + */ +CREATE OR REPLACE FUNCTION json_normalize_numeric_keys_matching(obj json, regexp text) + RETURNS json LANGUAGE SQL AS $$ +SELECT + coalesce(json_object_agg( + key, + CASE + WHEN key ~ regexp THEN + CASE json_typeof(value) + WHEN 'number' THEN 0::text::json + ELSE (-1)::text::json + END + ELSE value + END + ), '{}') +FROM + json_each(obj) +$$; + +-- explain only worker information, normalizing any values that could vary across executions +CREATE OR REPLACE FUNCTION explain_workers(plan_node json) + RETURNS json LANGUAGE SQL AS $$ +SELECT + coalesce(json_object_agg(key, value), '{}') +FROM ( + SELECT + key, + CASE key + WHEN 'Workers' THEN + (SELECT json_agg( + json_normalize_numeric_keys_matching(worker, '(Blocks|Time)$|Sort Space Used') + ) + FROM json_array_elements(value) AS workers(worker)) + WHEN 'Plans' THEN + (SELECT json_agg( + explain_workers(child) + ) + FROM json_array_elements(value) AS children(child)) + END AS value + FROM + json_each(plan_node) AS entries(key, value) + WHERE + key IN ('Workers', 'Plans') +) AS plan_fields(key, value); +$$; + +-- test that per-worker sort and buffers output is combined correctly in EXPLAIN +set force_parallel_mode = true; + +SELECT explain_workers(json_explain($$ + SELECT * FROM (VALUES(1),(2)) x ORDER BY x; +$$, 'verbose', 'analyze', 'buffers') -> 0 -> 'Plan'); + +SELECT regexp_replace(regexp_replace(text_explain($$ + SELECT * FROM (VALUES(1),(2)) x ORDER BY x; +$$, 'verbose', 'analyze', 'buffers', 'timing off', 'costs off', 'summary off'), + 'Buffers:.+$', 'Buffers: xxx', 'ng'), 'Sort Method:.+$', 'Sort Method: xxx', 'ng'); + +reset force_parallel_mode;