Merge pull request #3899 from citusdata/explain_analyze_sort_by_time

Include execution duration in worker_last_saved_explain_analyze

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
+ * If enabled, EXPLAIN ANALYZE output & other statistics of last worker task
- * SavedExplainPlan.
+ * 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();
+		int columnCount = tupleDescriptor->natts;
-	}
+		if (columnCount != 2)
-	else
 		{
-		PG_RETURN_TEXT_P(cstring_to_text(SavedExplainPlan));
+			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);
 }
 

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

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

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();
+SELECT explain_analyze_output FROM worker_last_saved_explain_analyze();
- 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();
+SELECT explain_analyze_output FROM worker_last_saved_explain_analyze();
-                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();
+SELECT explain_analyze_output FROM worker_last_saved_explain_analyze();
-            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();
+SELECT explain_analyze_output FROM worker_last_saved_explain_analyze();
-                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();
+SELECT explain_analyze_output FROM worker_last_saved_explain_analyze();
-               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();
+SELECT explain_analyze_output FROM worker_last_saved_explain_analyze();
-               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();
+SELECT explain_analyze_output FROM worker_last_saved_explain_analyze();
- worker_last_saved_explain_analyze
+     explain_analyze_output
 ---------------------------------------------------------------------
- Result (actual rows=1 loops=1)   +
+ Result (actual rows=1 loops=1)+
 
 (1 row)
 
@@ -1580,14 +1580,14 @@ SELECT * FROM worker_save_query_explain_analyze('SELECT 1', '{"format": "json",
  1
 (1 row)
 
-SELECT worker_last_saved_explain_analyze();
+SELECT explain_analyze_output FROM worker_last_saved_explain_analyze();
- worker_last_saved_explain_analyze
+     explain_analyze_output
 ---------------------------------------------------------------------
  [                             +
    {                           +
      "Plan": {                 +
        "Node Type": "Result",  +
-       "Parallel Aware": false,   +
+       "Parallel Aware": false,+
        "Actual Rows": 1,       +
        "Actual Loops": 1       +
      },                        +
@@ -1603,8 +1603,8 @@ SELECT * FROM worker_save_query_explain_analyze('SELECT 1', '{"format": "xml", "
  1
 (1 row)
 
-SELECT worker_last_saved_explain_analyze();
+SELECT explain_analyze_output FROM worker_last_saved_explain_analyze();
-            worker_last_saved_explain_analyze
+                  explain_analyze_output
 ---------------------------------------------------------------------
  <explain xmlns="http://www.postgresql.org/2009/explain">+
    <Query>                                               +
@@ -1626,12 +1626,12 @@ SELECT * FROM worker_save_query_explain_analyze('SELECT 1', '{"format": "yaml",
  1
 (1 row)
 
-SELECT worker_last_saved_explain_analyze();
+SELECT explain_analyze_output FROM worker_last_saved_explain_analyze();
- worker_last_saved_explain_analyze
+  explain_analyze_output
 ---------------------------------------------------------------------
  - Plan:                  +
      Node Type: "Result"  +
-     Parallel Aware: false        +
+     Parallel Aware: false+
      Actual Rows: 1       +
      Actual Loops: 1      +
    Triggers:
@@ -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;
+SELECT count(*) FROM worker_last_saved_explain_analyze();
- ?column?
+ 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;
+SELECT count(*) FROM worker_last_saved_explain_analyze();
- ?column?
+ 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
 ---------------------------------------------------------------------

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