Include execution duration in worker_last_saved_explain_analyze

2020-06-10 10:48:59 -07:00 · 2020-06-10 10:48:59 -07:00 · 0e3140c14d
parent 93b79880fe
commit 0e3140c14d
5 changed files with 130 additions and 84 deletions
--- 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);
 }

--- 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
--- 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
--- 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
 ---------------------------------------------------------------------
 <explain xmlns="http://www.postgresql.org/2009/explain">+
   <Query>                                               +
@ -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
 ---------------------------------------------------------------------
--- 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