From 0e3140c14dc3d575443e5e641df28b6eb689e57a Mon Sep 17 00:00:00 2001 From: Hadi Moshayedi Date: Wed, 10 Jun 2020 10:48:59 -0700 Subject: [PATCH] Include execution duration in worker_last_saved_explain_analyze --- .../distributed/planner/multi_explain.c | 51 ++++++-- .../9.4-1.sql | 2 +- .../latest.sql | 2 +- src/test/regress/expected/multi_explain.out | 117 ++++++++++-------- src/test/regress/sql/multi_explain.sql | 42 ++++--- 5 files changed, 130 insertions(+), 84 deletions(-) diff --git a/src/backend/distributed/planner/multi_explain.c b/src/backend/distributed/planner/multi_explain.c index 155f8fd77..ac0aaa769 100644 --- a/src/backend/distributed/planner/multi_explain.c +++ b/src/backend/distributed/planner/multi_explain.c @@ -70,10 +70,11 @@ bool ExplainDistributedQueries = true; bool ExplainAllTasks = false; /* - * If enabled, EXPLAIN ANALYZE output of last worker task are saved in - * SavedExplainPlan. + * If enabled, EXPLAIN ANALYZE output & other statistics of last worker task + * are saved in following variables. */ static char *SavedExplainPlan = NULL; +static double SavedExecutionDurationMillisec = 0.0; /* struct to save explain flags */ typedef struct @@ -131,7 +132,8 @@ static void ExplainWorkerPlan(PlannedStmt *plannedStmt, DestReceiver *dest, ExplainState *es, const char *queryString, ParamListInfo params, QueryEnvironment *queryEnv, - const instr_time *planduration); + const instr_time *planduration, + double *executionDurationMillisec); static bool ExtractFieldBoolean(Datum jsonbDoc, const char *fieldName, bool defaultValue); static ExplainFormat ExtractFieldExplainFormat(Datum jsonbDoc, const char *fieldName, ExplainFormat defaultValue); @@ -807,14 +809,30 @@ worker_last_saved_explain_analyze(PG_FUNCTION_ARGS) { CheckCitusVersion(ERROR); - if (SavedExplainPlan == NULL) + TupleDesc tupleDescriptor = NULL; + Tuplestorestate *tupleStore = SetupTuplestore(fcinfo, &tupleDescriptor); + + if (SavedExplainPlan != NULL) { - PG_RETURN_NULL(); - } - else - { - PG_RETURN_TEXT_P(cstring_to_text(SavedExplainPlan)); + int columnCount = tupleDescriptor->natts; + if (columnCount != 2) + { + ereport(ERROR, (errmsg("expected 3 output columns in definition of " + "worker_last_saved_explain_analyze, but got %d", + columnCount))); + } + + bool columnNulls[2] = { false }; + Datum columnValues[2] = { + CStringGetTextDatum(SavedExplainPlan), + Float8GetDatum(SavedExecutionDurationMillisec) + }; + + tuplestore_putvalues(tupleStore, tupleDescriptor, columnValues, columnNulls); } + + tuplestore_donestoring(tupleStore); + PG_RETURN_DATUM(0); } @@ -829,6 +847,7 @@ worker_save_query_explain_analyze(PG_FUNCTION_ARGS) text *queryText = PG_GETARG_TEXT_P(0); char *queryString = text_to_cstring(queryText); + double executionDurationMillisec = 0.0; Datum explainOptions = PG_GETARG_DATUM(1); ExplainState *es = NewExplainState(); @@ -879,7 +898,8 @@ worker_save_query_explain_analyze(PG_FUNCTION_ARGS) INSTR_TIME_SUBTRACT(planDuration, planStart); /* do the actual EXPLAIN ANALYZE */ - ExplainWorkerPlan(plan, tupleStoreDest, es, queryString, NULL, NULL, &planDuration); + ExplainWorkerPlan(plan, tupleStoreDest, es, queryString, NULL, NULL, + &planDuration, &executionDurationMillisec); ExplainEndOutput(es); @@ -890,6 +910,7 @@ worker_save_query_explain_analyze(PG_FUNCTION_ARGS) FreeSavedExplainPlan(); SavedExplainPlan = pstrdup(es->str->data); + SavedExecutionDurationMillisec = executionDurationMillisec; MemoryContextSwitchTo(oldContext); @@ -1187,7 +1208,8 @@ ExplainAnalyzeTaskList(List *originalTaskList, Task *explainAnalyzeTask = copyObject(originalTask); const char *queryString = TaskQueryStringForAllPlacements(explainAnalyzeTask); char *wrappedQuery = WrapQueryForExplainAnalyze(queryString, tupleDesc); - char *fetchQuery = "SELECT worker_last_saved_explain_analyze()"; + char *fetchQuery = + "SELECT explain_analyze_output FROM worker_last_saved_explain_analyze()"; SetTaskQueryStringList(explainAnalyzeTask, list_make2(wrappedQuery, fetchQuery)); TupleDestination *originalTaskDest = originalTask->tupleDest ? @@ -1339,7 +1361,8 @@ ExplainOneQuery(Query *query, int cursorOptions, /* * ExplainAnalyzeWorkerPlan produces explain output into es. If es->analyze, it also executes - * the given plannedStmt and sends the results to dest. + * the given plannedStmt and sends the results to dest. It puts total time to execute in + * executionDurationMillisec. * * This is based on postgres' ExplainOnePlan(). We couldn't use an IntoClause to store results * into tupleStore, so we had to copy the same functionality with some minor changes. @@ -1352,7 +1375,7 @@ ExplainOneQuery(Query *query, int cursorOptions, static void ExplainWorkerPlan(PlannedStmt *plannedstmt, DestReceiver *dest, ExplainState *es, const char *queryString, ParamListInfo params, QueryEnvironment *queryEnv, - const instr_time *planduration) + const instr_time *planduration, double *executionDurationMillisec) { QueryDesc *queryDesc; instr_time starttime; @@ -1466,6 +1489,8 @@ ExplainWorkerPlan(PlannedStmt *plannedstmt, DestReceiver *dest, ExplainState *es ExplainPropertyFloat("Execution Time", "ms", 1000.0 * totaltime, 3, es); + *executionDurationMillisec = totaltime * 1000; + ExplainCloseGroup("Query", NULL, true, es); } diff --git a/src/backend/distributed/sql/udfs/worker_last_saved_explain_analyze/9.4-1.sql b/src/backend/distributed/sql/udfs/worker_last_saved_explain_analyze/9.4-1.sql index dc47b9985..17a5a15c5 100644 --- a/src/backend/distributed/sql/udfs/worker_last_saved_explain_analyze/9.4-1.sql +++ b/src/backend/distributed/sql/udfs/worker_last_saved_explain_analyze/9.4-1.sql @@ -1,6 +1,6 @@ CREATE OR REPLACE FUNCTION pg_catalog.worker_last_saved_explain_analyze() - RETURNS TEXT + RETURNS TABLE(explain_analyze_output TEXT, execution_duration DOUBLE PRECISION) LANGUAGE C STRICT AS 'citus'; COMMENT ON FUNCTION pg_catalog.worker_last_saved_explain_analyze() IS diff --git a/src/backend/distributed/sql/udfs/worker_last_saved_explain_analyze/latest.sql b/src/backend/distributed/sql/udfs/worker_last_saved_explain_analyze/latest.sql index dc47b9985..17a5a15c5 100644 --- a/src/backend/distributed/sql/udfs/worker_last_saved_explain_analyze/latest.sql +++ b/src/backend/distributed/sql/udfs/worker_last_saved_explain_analyze/latest.sql @@ -1,6 +1,6 @@ CREATE OR REPLACE FUNCTION pg_catalog.worker_last_saved_explain_analyze() - RETURNS TEXT + RETURNS TABLE(explain_analyze_output TEXT, execution_duration DOUBLE PRECISION) LANGUAGE C STRICT AS 'citus'; COMMENT ON FUNCTION pg_catalog.worker_last_saved_explain_analyze() IS diff --git a/src/test/regress/expected/multi_explain.out b/src/test/regress/expected/multi_explain.out index 30845aea3..2762a2a43 100644 --- a/src/test/regress/expected/multi_explain.out +++ b/src/test/regress/expected/multi_explain.out @@ -1437,10 +1437,10 @@ SELECT * FROM worker_save_query_explain_analyze('SELECT 1', :default_opts) as (a 1 (1 row) -SELECT worker_last_saved_explain_analyze(); - worker_last_saved_explain_analyze +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); + explain_analyze_output --------------------------------------------------------------------- - Result (actual rows=1 loops=1) + + Result (actual rows=1 loops=1)+ (1 row) @@ -1454,8 +1454,8 @@ SELECT * FROM worker_save_query_explain_analyze($Q$ --------------------------------------------------------------------- (0 rows) -SELECT worker_last_saved_explain_analyze(); - worker_last_saved_explain_analyze +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); + explain_analyze_output --------------------------------------------------------------------- Insert on explain_analyze_test (actual rows=0 loops=1) + -> Function Scan on generate_series i (actual rows=5 loops=1)+ @@ -1475,8 +1475,8 @@ SELECT * FROM worker_save_query_explain_analyze($Q$SELECT * FROM explain_analyze 4 | value 4 (4 rows) -SELECT worker_last_saved_explain_analyze(); - worker_last_saved_explain_analyze +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); + explain_analyze_output --------------------------------------------------------------------- Seq Scan on explain_analyze_test (actual rows=4 loops=1)+ @@ -1498,8 +1498,8 @@ SELECT * FROM worker_save_query_explain_analyze($Q$ 5 | 5 (5 rows) -SELECT worker_last_saved_explain_analyze(); - worker_last_saved_explain_analyze +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); + explain_analyze_output --------------------------------------------------------------------- Insert on explain_analyze_test (actual rows=5 loops=1) + -> Function Scan on generate_series i (actual rows=5 loops=1)+ @@ -1519,8 +1519,8 @@ SELECT * FROM worker_save_query_explain_analyze($Q$ 4 | value 4 (2 rows) -SELECT worker_last_saved_explain_analyze(); - worker_last_saved_explain_analyze +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); + explain_analyze_output --------------------------------------------------------------------- Delete on explain_analyze_test (actual rows=2 loops=1) + -> Seq Scan on explain_analyze_test (actual rows=2 loops=1)+ @@ -1539,8 +1539,8 @@ SELECT * FROM worker_save_query_explain_analyze($Q$ --------------------------------------------------------------------- (0 rows) -SELECT worker_last_saved_explain_analyze(); - worker_last_saved_explain_analyze +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); + explain_analyze_output --------------------------------------------------------------------- Delete on explain_analyze_test (actual rows=0 loops=1) + -> Seq Scan on explain_analyze_test (actual rows=2 loops=1)+ @@ -1567,10 +1567,10 @@ SELECT * FROM worker_save_query_explain_analyze('SELECT 1', '{"format": "text", 1 (1 row) -SELECT worker_last_saved_explain_analyze(); - worker_last_saved_explain_analyze +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); + explain_analyze_output --------------------------------------------------------------------- - Result (actual rows=1 loops=1) + + Result (actual rows=1 loops=1)+ (1 row) @@ -1580,20 +1580,20 @@ SELECT * FROM worker_save_query_explain_analyze('SELECT 1', '{"format": "json", 1 (1 row) -SELECT worker_last_saved_explain_analyze(); - worker_last_saved_explain_analyze +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); + explain_analyze_output --------------------------------------------------------------------- - [ + - { + - "Plan": { + - "Node Type": "Result", + - "Parallel Aware": false, + - "Actual Rows": 1, + - "Actual Loops": 1 + - }, + - "Triggers": [ + - ] + - } + + [ + + { + + "Plan": { + + "Node Type": "Result", + + "Parallel Aware": false,+ + "Actual Rows": 1, + + "Actual Loops": 1 + + }, + + "Triggers": [ + + ] + + } + ] (1 row) @@ -1603,8 +1603,8 @@ SELECT * FROM worker_save_query_explain_analyze('SELECT 1', '{"format": "xml", " 1 (1 row) -SELECT worker_last_saved_explain_analyze(); - worker_last_saved_explain_analyze +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); + explain_analyze_output --------------------------------------------------------------------- + + @@ -1626,14 +1626,14 @@ SELECT * FROM worker_save_query_explain_analyze('SELECT 1', '{"format": "yaml", 1 (1 row) -SELECT worker_last_saved_explain_analyze(); - worker_last_saved_explain_analyze +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); + explain_analyze_output --------------------------------------------------------------------- - - Plan: + - Node Type: "Result" + - Parallel Aware: false + - Actual Rows: 1 + - Actual Loops: 1 + + - Plan: + + Node Type: "Result" + + Parallel Aware: false+ + Actual Rows: 1 + + Actual Loops: 1 + Triggers: (1 row) @@ -1649,7 +1649,7 @@ SELECT * FROM worker_save_query_explain_analyze('SELECT * FROM explain_analyze_t 4 (4 rows) -SELECT worker_last_saved_explain_analyze() ~ 'Seq Scan.*\(cost=0.00.*\) \(actual rows.*\)'; +SELECT explain_analyze_output ~ 'Seq Scan.*\(cost=0.00.*\) \(actual rows.*\)' FROM worker_last_saved_explain_analyze(); ?column? --------------------------------------------------------------------- t @@ -1667,7 +1667,7 @@ SELECT * FROM worker_save_query_explain_analyze('SELECT * FROM explain_analyze_t 4 (4 rows) -SELECT worker_last_saved_explain_analyze() ~ 'Seq Scan on explain_analyze_test \(actual time=.* rows=.* loops=1\)'; +SELECT explain_analyze_output ~ 'Seq Scan on explain_analyze_test \(actual time=.* rows=.* loops=1\)' FROM worker_last_saved_explain_analyze(); ?column? --------------------------------------------------------------------- t @@ -1682,7 +1682,7 @@ SELECT * FROM worker_save_query_explain_analyze('SELECT 1', '{"timing": false, " 1 (1 row) -SELECT worker_last_saved_explain_analyze() ~ 'Planning Time:.*Execution Time:.*'; +SELECT explain_analyze_output ~ 'Planning Time:.*Execution Time:.*' FROM worker_last_saved_explain_analyze(); ?column? --------------------------------------------------------------------- t @@ -1700,7 +1700,7 @@ SELECT * FROM worker_save_query_explain_analyze('SELECT * FROM explain_analyze_t 4 (4 rows) -SELECT worker_last_saved_explain_analyze() ~ 'Buffers:'; +SELECT explain_analyze_output ~ 'Buffers:' FROM worker_last_saved_explain_analyze(); ?column? --------------------------------------------------------------------- t @@ -1718,7 +1718,7 @@ SELECT * FROM worker_save_query_explain_analyze('SELECT * FROM explain_analyze_t 4 (4 rows) -SELECT worker_last_saved_explain_analyze() ~ 'Output: a, b'; +SELECT explain_analyze_output ~ 'Output: a, b' FROM worker_last_saved_explain_analyze(); ?column? --------------------------------------------------------------------- t @@ -1732,10 +1732,10 @@ SELECT * FROM worker_save_query_explain_analyze('SELECT 1', '{}') as (a int); 1 (1 row) -SELECT worker_last_saved_explain_analyze() IS NULL; - ?column? +SELECT count(*) FROM worker_last_saved_explain_analyze(); + count --------------------------------------------------------------------- - t + 0 (1 row) -- should be deleted at the end of prepare commit @@ -1745,20 +1745,35 @@ SELECT * FROM worker_save_query_explain_analyze('UPDATE explain_analyze_test SET --------------------------------------------------------------------- (0 rows) -SELECT worker_last_saved_explain_analyze() IS NOT NULL; - ?column? +SELECT count(*) FROM worker_last_saved_explain_analyze(); + count --------------------------------------------------------------------- - t + 1 (1 row) PREPARE TRANSACTION 'citus_0_1496350_7_0'; -SELECT worker_last_saved_explain_analyze() IS NULL; +SELECT count(*) FROM worker_last_saved_explain_analyze(); + count +--------------------------------------------------------------------- + 0 +(1 row) + +COMMIT PREPARED 'citus_0_1496350_7_0'; +-- verify execution time makes sense +BEGIN; +SELECT count(*) FROM worker_save_query_explain_analyze('SELECT pg_sleep(0.05)', :default_opts) as (a int); + count +--------------------------------------------------------------------- + 1 +(1 row) + +SELECT execution_duration BETWEEN 30 AND 200 FROM worker_last_saved_explain_analyze(); ?column? --------------------------------------------------------------------- t (1 row) -COMMIT PREPARED 'citus_0_1496350_7_0'; +END; SELECT * FROM explain_analyze_test ORDER BY a; a | b --------------------------------------------------------------------- diff --git a/src/test/regress/sql/multi_explain.sql b/src/test/regress/sql/multi_explain.sql index 2191b6767..6c1caafbd 100644 --- a/src/test/regress/sql/multi_explain.sql +++ b/src/test/regress/sql/multi_explain.sql @@ -636,7 +636,7 @@ INSERT INTO explain_analyze_test VALUES (1, 'value 1'), (2, 'value 2'), (3, 'val -- simple select BEGIN; SELECT * FROM worker_save_query_explain_analyze('SELECT 1', :default_opts) as (a int); -SELECT worker_last_saved_explain_analyze(); +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); END; -- insert into select @@ -644,14 +644,14 @@ BEGIN; SELECT * FROM worker_save_query_explain_analyze($Q$ INSERT INTO explain_analyze_test SELECT i, i::text FROM generate_series(1, 5) i $Q$, :default_opts) as (a int); -SELECT worker_last_saved_explain_analyze(); +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); ROLLBACK; -- select from table BEGIN; SELECT * FROM worker_save_query_explain_analyze($Q$SELECT * FROM explain_analyze_test$Q$, :default_opts) as (a int, b text); -SELECT worker_last_saved_explain_analyze(); +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); ROLLBACK; -- insert into with returning @@ -660,7 +660,7 @@ SELECT * FROM worker_save_query_explain_analyze($Q$ INSERT INTO explain_analyze_test SELECT i, i::text FROM generate_series(1, 5) i RETURNING a, b$Q$, :default_opts) as (a int, b text); -SELECT worker_last_saved_explain_analyze(); +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); ROLLBACK; -- delete with returning @@ -669,7 +669,7 @@ SELECT * FROM worker_save_query_explain_analyze($Q$ DELETE FROM explain_analyze_test WHERE a % 2 = 0 RETURNING a, b$Q$, :default_opts) as (a int, b text); -SELECT worker_last_saved_explain_analyze(); +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); ROLLBACK; -- delete without returning @@ -677,7 +677,7 @@ BEGIN; SELECT * FROM worker_save_query_explain_analyze($Q$ DELETE FROM explain_analyze_test WHERE a % 2 = 0$Q$, :default_opts) as (a int); -SELECT worker_last_saved_explain_analyze(); +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); ROLLBACK; -- multiple queries (should ERROR) @@ -692,57 +692,63 @@ SELECT * FROM worker_save_query_explain_analyze('SELECT 1', '{"format": "invlaid -- test formats BEGIN; SELECT * FROM worker_save_query_explain_analyze('SELECT 1', '{"format": "text", "costs": false}') as (a int); -SELECT worker_last_saved_explain_analyze(); +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); SELECT * FROM worker_save_query_explain_analyze('SELECT 1', '{"format": "json", "costs": false}') as (a int); -SELECT worker_last_saved_explain_analyze(); +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); SELECT * FROM worker_save_query_explain_analyze('SELECT 1', '{"format": "xml", "costs": false}') as (a int); -SELECT worker_last_saved_explain_analyze(); +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); SELECT * FROM worker_save_query_explain_analyze('SELECT 1', '{"format": "yaml", "costs": false}') as (a int); -SELECT worker_last_saved_explain_analyze(); +SELECT explain_analyze_output FROM worker_last_saved_explain_analyze(); END; -- costs on, timing off BEGIN; SELECT * FROM worker_save_query_explain_analyze('SELECT * FROM explain_analyze_test', '{"timing": false, "costs": true}') as (a int); -SELECT worker_last_saved_explain_analyze() ~ 'Seq Scan.*\(cost=0.00.*\) \(actual rows.*\)'; +SELECT explain_analyze_output ~ 'Seq Scan.*\(cost=0.00.*\) \(actual rows.*\)' FROM worker_last_saved_explain_analyze(); END; -- costs off, timing on BEGIN; SELECT * FROM worker_save_query_explain_analyze('SELECT * FROM explain_analyze_test', '{"timing": true, "costs": false}') as (a int); -SELECT worker_last_saved_explain_analyze() ~ 'Seq Scan on explain_analyze_test \(actual time=.* rows=.* loops=1\)'; +SELECT explain_analyze_output ~ 'Seq Scan on explain_analyze_test \(actual time=.* rows=.* loops=1\)' FROM worker_last_saved_explain_analyze(); END; -- summary on BEGIN; SELECT * FROM worker_save_query_explain_analyze('SELECT 1', '{"timing": false, "costs": false, "summary": true}') as (a int); -SELECT worker_last_saved_explain_analyze() ~ 'Planning Time:.*Execution Time:.*'; +SELECT explain_analyze_output ~ 'Planning Time:.*Execution Time:.*' FROM worker_last_saved_explain_analyze(); END; -- buffers on BEGIN; SELECT * FROM worker_save_query_explain_analyze('SELECT * FROM explain_analyze_test', '{"timing": false, "costs": false, "buffers": true}') as (a int); -SELECT worker_last_saved_explain_analyze() ~ 'Buffers:'; +SELECT explain_analyze_output ~ 'Buffers:' FROM worker_last_saved_explain_analyze(); END; -- verbose on BEGIN; SELECT * FROM worker_save_query_explain_analyze('SELECT * FROM explain_analyze_test', '{"timing": false, "costs": false, "verbose": true}') as (a int); -SELECT worker_last_saved_explain_analyze() ~ 'Output: a, b'; +SELECT explain_analyze_output ~ 'Output: a, b' FROM worker_last_saved_explain_analyze(); END; -- make sure deleted at transaction end SELECT * FROM worker_save_query_explain_analyze('SELECT 1', '{}') as (a int); -SELECT worker_last_saved_explain_analyze() IS NULL; +SELECT count(*) FROM worker_last_saved_explain_analyze(); -- should be deleted at the end of prepare commit BEGIN; SELECT * FROM worker_save_query_explain_analyze('UPDATE explain_analyze_test SET a=6 WHERE a=4', '{}') as (a int); -SELECT worker_last_saved_explain_analyze() IS NOT NULL; +SELECT count(*) FROM worker_last_saved_explain_analyze(); PREPARE TRANSACTION 'citus_0_1496350_7_0'; -SELECT worker_last_saved_explain_analyze() IS NULL; +SELECT count(*) FROM worker_last_saved_explain_analyze(); COMMIT PREPARED 'citus_0_1496350_7_0'; +-- verify execution time makes sense +BEGIN; +SELECT count(*) FROM worker_save_query_explain_analyze('SELECT pg_sleep(0.05)', :default_opts) as (a int); +SELECT execution_duration BETWEEN 30 AND 200 FROM worker_last_saved_explain_analyze(); +END; + SELECT * FROM explain_analyze_test ORDER BY a; \a\t