Merge cockroachdb#56524

56524: sql: introduce EXPLAIN ANALYZE (PLAN) r=RaduBerinde a=RaduBerinde

#### sql: introduce EXPLAIN ANALYZE (PLAN)

This change introduces a new variant of `EXPLAIN ANALYZE` which
executes the query and returns the execution plan (in the future,
annotated with stats from execution).

Note that `(PLAN)` is the default mode for the regular `EXPLAIN`.
Currently `EXPLAIN ANALYZE` defaults to `(DISTSQL)` mode, but we plan
to switch that default to the `(PLAN)` version once it is fully
implemented.

Release note (sql change): Added a new variant of explain: EXPLAIN
ANALYZE (PLAN).

#### sql: add planning and execution time to EXPLAIN ANALYZE (PLAN)

This commit adds planning and execution time as top-level fields in
EXPLAIN ANALYZE (PLAN). We also plumb a testing knob to allow these
fields to be deterministic in tests.

Release note: None

![image](https://user-images.githubusercontent.com/16544120/98735878-f33eb780-2358-11eb-8c3e-657d4e2df589.png)


Co-authored-by: Radu Berinde <[email protected]>

pkg/sql/conn_executor_exec.go

@@ -23,6 +23,7 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/settings/cluster"
 	"github.com/cockroachdb/cockroach/pkg/sql/catalog/colinfo"
 	"github.com/cockroachdb/cockroach/pkg/sql/catalog/descs"
+	"github.com/cockroachdb/cockroach/pkg/sql/opt/exec/explain"
 	"github.com/cockroachdb/cockroach/pkg/sql/paramparse"
 	"github.com/cockroachdb/cockroach/pkg/sql/parser"
 	"github.com/cockroachdb/cockroach/pkg/sql/pgwire/pgcode"
@@ -341,12 +342,19 @@ func (ex *connExecutor) execStmtInOpenState(
 	p.noticeSender = res
 	ih := &p.instrumentation
 
-	if explain, ok := ast.(*tree.ExplainAnalyze); ok && explain.Mode == tree.ExplainDebug {
-		telemetry.Inc(sqltelemetry.ExplainAnalyzeDebugUseCounter)
-		ih.SetOutputMode(explainAnalyzeDebugOutput)
+	if e, ok := ast.(*tree.ExplainAnalyze); ok &&
+		(e.Mode == tree.ExplainDebug || e.Mode == tree.ExplainPlan) {
+		if e.Mode == tree.ExplainDebug {
+			telemetry.Inc(sqltelemetry.ExplainAnalyzeDebugUseCounter)
+			ih.SetOutputMode(explainAnalyzeDebugOutput, explain.Flags{})
+		} else {
+			telemetry.Inc(sqltelemetry.ExplainAnalyzeUseCounter)
+			flags := explain.MakeFlags(&e.ExplainOptions)
+			ih.SetOutputMode(explainAnalyzePlanOutput, flags)
+		}
 		// Strip off the explain node to execute the inner statement.
-		stmt.AST = explain.Statement
-		ast = stmt.AST
+		stmt.AST = e.Statement
+		ast = e.Statement
 		// TODO(radu): should we trim the "EXPLAIN ANALYZE (DEBUG)" part from
 		// stmt.SQL?
 
@@ -364,7 +372,7 @@ func (ex *connExecutor) execStmtInOpenState(
 	if needFinish {
 		sql := stmt.SQL
 		defer func() {
-			retErr = ih.Finish(ex.server.cfg, ex.appStats, p, ast, sql, res, retErr)
+			retErr = ih.Finish(ex.server.cfg, ex.appStats, ex.statsCollector, p, ast, sql, res, retErr)
 		}()
 		// TODO(radu): consider removing this if/when #46164 is addressed.
 		p.extendedEvalCtx.Context = ctx

pkg/sql/exec_util.go

@@ -832,6 +832,13 @@ type ExecutorTestingKnobs struct {
 	// lifetime of this function. Note that returning a nil function is
 	// unsupported and will lead to a panic.
 	TestingSaveFlows func(stmt string) func(map[roachpb.NodeID]*execinfrapb.FlowSpec) error
+
+	// DeterministicExplainAnalyze, if set, will result in overriding fields in
+	// EXPLAIN ANALYZE (PLAN) that can vary between runs (like elapsed times).
+	//
+	// Should be set together with execinfra.TestingKnobs.DeterministicStats.
+	// TODO(radu): figure out how to unify these two.
+	DeterministicExplainAnalyze bool
 }
 
 // PGWireTestingKnobs contains knobs for the pgwire module.

pkg/sql/explain_tree_test.go

@@ -78,7 +78,7 @@ func TestPlanToTreeAndPlanToString(t *testing.T) {
 			p.curPlan.flags.Set(planFlagExecDone)
 			p.curPlan.close(ctx)
 			if d.Cmd == "plan-string" {
-				return ih.planString()
+				return ih.planStringForBundle()
 			}
 			treeYaml, err := yaml.Marshal(ih.PlanForStats(ctx))
 			if err != nil {

pkg/sql/instrumentation.go

@@ -13,10 +13,12 @@ package sql
 import (
 	"context"
 	"fmt"
+	"time"
 
 	"github.com/cockroachdb/cockroach/pkg/keys"
 	"github.com/cockroachdb/cockroach/pkg/roachpb"
 	"github.com/cockroachdb/cockroach/pkg/server/telemetry"
+	"github.com/cockroachdb/cockroach/pkg/sql/catalog/colinfo"
 	"github.com/cockroachdb/cockroach/pkg/sql/opt/exec/explain"
 	"github.com/cockroachdb/cockroach/pkg/sql/physicalplan"
 	"github.com/cockroachdb/cockroach/pkg/sql/sem/tree"
@@ -42,6 +44,8 @@ import (
 //
 type instrumentationHelper struct {
 	outputMode outputMode
+	// explainFlags is used when outputMode is explainAnalyzePlanOutput.
+	explainFlags explain.Flags
 
 	// Query fingerprint (anonymized statement).
 	fingerprint string
@@ -84,12 +88,14 @@ type outputMode int8
 const (
 	unmodifiedOutput outputMode = iota
 	explainAnalyzeDebugOutput
+	explainAnalyzePlanOutput
 )
 
 // SetOutputMode can be called before Setup, if we are running an EXPLAIN
 // ANALYZE variant.
-func (ih *instrumentationHelper) SetOutputMode(outputMode outputMode) {
+func (ih *instrumentationHelper) SetOutputMode(outputMode outputMode, explainFlags explain.Flags) {
 	ih.outputMode = outputMode
+	ih.explainFlags = explainFlags
 }
 
 // Setup potentially enables snowball tracing for the statement, depending on
@@ -109,14 +115,19 @@ func (ih *instrumentationHelper) Setup(
 	ih.implicitTxn = implicitTxn
 	ih.codec = cfg.Codec
 
-	if ih.outputMode == explainAnalyzeDebugOutput {
+	switch ih.outputMode {
+	case explainAnalyzeDebugOutput:
 		ih.collectBundle = true
 		// EXPLAIN ANALYZE (DEBUG) does not return the rows for the given query;
 		// instead it returns some text which includes a URL.
 		// TODO(radu): maybe capture some of the rows and include them in the
 		// bundle.
 		ih.discardRows = true
-	} else {
+
+	case explainAnalyzePlanOutput:
+		ih.discardRows = true
+
+	default:
 		ih.collectBundle, ih.diagRequestID, ih.finishCollectionDiagnostics =
 			stmtDiagnosticsRecorder.ShouldCollectDiagnostics(ctx, fingerprint)
 	}
@@ -125,7 +136,7 @@ func (ih *instrumentationHelper) Setup(
 
 	ih.savePlanForStats = appStats.shouldSaveLogicalPlanDescription(fingerprint, implicitTxn)
 
-	if !ih.collectBundle && ih.withStatementTrace == nil {
+	if !ih.collectBundle && ih.withStatementTrace == nil && ih.outputMode == unmodifiedOutput {
 		return ctx, false
 	}
 
@@ -138,6 +149,7 @@ func (ih *instrumentationHelper) Setup(
 func (ih *instrumentationHelper) Finish(
 	cfg *ExecutorConfig,
 	appStats *appStats,
+	statsCollector *sqlStatsCollector,
 	p *planner,
 	ast tree.Statement,
 	stmtRawSQL string,
@@ -158,7 +170,7 @@ func (ih *instrumentationHelper) Finish(
 	placeholders := p.extendedEvalCtx.Placeholders
 	if ih.collectBundle {
 		bundle := buildStatementBundle(
-			ih.origCtx, cfg.DB, ie, &p.curPlan, ih.planString(), trace, placeholders,
+			ih.origCtx, cfg.DB, ie, &p.curPlan, ih.planStringForBundle(), trace, placeholders,
 		)
 		bundle.insert(ctx, ih.fingerprint, ast, cfg.StmtDiagnosticsRecorder, ih.diagRequestID)
 		if ih.finishCollectionDiagnostics != nil {
@@ -172,10 +184,19 @@ func (ih *instrumentationHelper) Finish(
 			retErr = setExplainBundleResult(ctx, res, bundle, cfg)
 		}
 	}
+
 	if ih.withStatementTrace != nil {
 		ih.withStatementTrace(trace, stmtRawSQL)
 	}
 
+	if ih.outputMode == explainAnalyzePlanOutput && retErr == nil {
+		phaseTimes := &statsCollector.phaseTimes
+		if cfg.TestingKnobs.DeterministicExplainAnalyze {
+			phaseTimes = &deterministicPhaseTimes
+		}
+		retErr = ih.setExplainAnalyzePlanResult(ctx, res, phaseTimes)
+	}
+
 	// TODO(radu): this should be unified with other stmt stats accesses.
 	stmtStats, _ := appStats.getStatsForStmt(ih.fingerprint, ih.implicitTxn, retErr, false)
 	if stmtStats != nil {
@@ -229,7 +250,7 @@ func (ih *instrumentationHelper) ShouldCollectBundle() bool {
 // ShouldBuildExplainPlan returns true if we should build an explain plan and
 // call RecordExplainPlan.
 func (ih *instrumentationHelper) ShouldBuildExplainPlan() bool {
-	return ih.collectBundle || ih.savePlanForStats
+	return ih.collectBundle || ih.savePlanForStats || ih.outputMode == explainAnalyzePlanOutput
 }
 
 // RecordExplainPlan records the explain.Plan for this query.
@@ -263,8 +284,8 @@ func (ih *instrumentationHelper) PlanForStats(ctx context.Context) *roachpb.Expl
 	return ob.BuildProtoTree()
 }
 
-// planString generates the plan tree as a string; used internally for bundles.
-func (ih *instrumentationHelper) planString() string {
+// planStringForBundle generates the plan tree as a string; used internally for bundles.
+func (ih *instrumentationHelper) planStringForBundle() string {
 	if ih.explainPlan == nil {
 		return ""
 	}
@@ -277,3 +298,54 @@ func (ih *instrumentationHelper) planString() string {
 	}
 	return ob.BuildString()
 }
+
+// planRowsForExplainAnalyze generates the plan tree as a list of strings (one
+// for each line).
+// Used in explainAnalyzePlanOutput mode.
+func (ih *instrumentationHelper) planRowsForExplainAnalyze(phaseTimes *phaseTimes) []string {
+	if ih.explainPlan == nil {
+		return nil
+	}
+	ob := explain.NewOutputBuilder(ih.explainFlags)
+	ob.AddField("planning time", phaseTimes.getPlanningLatency().Round(time.Microsecond).String())
+	ob.AddField("execution time", phaseTimes.getRunLatency().Round(time.Microsecond).String())
+	if err := emitExplain(ob, ih.evalCtx, ih.codec, ih.explainPlan, ih.distribution, ih.vectorized); err != nil {
+		return []string{fmt.Sprintf("error emitting plan: %v", err)}
+	}
+	return ob.BuildStringRows()
+}
+
+// setExplainAnalyzePlanResult sets the result for an EXPLAIN ANALYZE (PLAN)
+// statement. It returns an error only if there was an error adding rows to the
+// result.
+func (ih *instrumentationHelper) setExplainAnalyzePlanResult(
+	ctx context.Context, res RestrictedCommandResult, phaseTimes *phaseTimes,
+) (commErr error) {
+	res.ResetStmtType(&tree.ExplainAnalyze{})
+	res.SetColumns(ctx, colinfo.ExplainPlanColumns)
+
+	if res.Err() != nil {
+		// Can't add rows if there was an error.
+		return nil //nolint:returnerrcheck
+	}
+
+	rows := ih.planRowsForExplainAnalyze(phaseTimes)
+	rows = append(rows, "")
+	rows = append(rows, "WARNING: this statement is experimental!")
+	for _, row := range rows {
+		if err := res.AddRow(ctx, tree.Datums{tree.NewDString(row)}); err != nil {
+			return err
+		}
+	}
+	return nil
+}
+
+var deterministicPhaseTimes = phaseTimes{
+	sessionQueryReceived:    time.Time{},
+	sessionStartParse:       time.Time{},
+	sessionEndParse:         time.Time{}.Add(1 * time.Microsecond),
+	plannerStartLogicalPlan: time.Time{}.Add(1 * time.Microsecond),
+	plannerEndLogicalPlan:   time.Time{}.Add(11 * time.Microsecond),
+	plannerStartExecStmt:    time.Time{}.Add(11 * time.Microsecond),
+	plannerEndExecStmt:      time.Time{}.Add(111 * time.Microsecond),
+}

pkg/sql/logictest/BUILD.bazel

@@ -13,6 +13,7 @@ go_library(
         "//pkg/security",
         "//pkg/server",
         "//pkg/settings/cluster",
+        "//pkg/sql",
         "//pkg/sql/execinfra",
         "//pkg/sql/mutations",
         "//pkg/sql/parser",

pkg/sql/logictest/logic.go

@@ -44,6 +44,7 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/security"
 	"github.com/cockroachdb/cockroach/pkg/server"
 	"github.com/cockroachdb/cockroach/pkg/settings/cluster"
+	"github.com/cockroachdb/cockroach/pkg/sql"
 	"github.com/cockroachdb/cockroach/pkg/sql/execinfra"
 	"github.com/cockroachdb/cockroach/pkg/sql/mutations"
 	"github.com/cockroachdb/cockroach/pkg/sql/parser"
@@ -1286,6 +1287,9 @@ func (t *logicTest) setup(cfg testClusterConfig, serverArgs TestServerArgs) {
 					DisableOptimizerRuleProbability: *disableOptRuleProbability,
 					OptimizerCostPerturbation:       *optimizerCostPerturbation,
 				},
+				SQLExecutor: &sql.ExecutorTestingKnobs{
+					DeterministicExplainAnalyze: true,
+				},
 			},
 			ClusterName: "testclustername",
 			UseDatabase: "test",

pkg/sql/logictest/testdata/logic_test/explain_analyze

@@ -40,6 +40,43 @@ EXPLAIN ANALYZE (DISTSQL) DELETE FROM a
 statement ok
 EXPLAIN ANALYZE (DISTSQL) DROP TABLE a
 
+statement ok
+EXPLAIN ANALYZE (PLAN) CREATE TABLE a (a INT PRIMARY KEY)
+
+statement ok
+EXPLAIN ANALYZE (PLAN) CREATE INDEX ON a(a)
+
+statement ok
+EXPLAIN ANALYZE (PLAN) INSERT INTO a VALUES (1)
+
+# Make sure failures are okay.
+statement error duplicate
+EXPLAIN ANALYZE (PLAN) INSERT INTO a VALUES (1)
+
+statement error value type string doesn't match type int of column "a"
+EXPLAIN ANALYZE (PLAN) INSERT INTO a VALUES ('a'::string)
+
+statement ok
+EXPLAIN ANALYZE (PLAN) INSERT INTO a SELECT a+1 FROM a
+
+statement ok
+EXPLAIN ANALYZE (PLAN) UPDATE a SET a = a*3
+
+statement ok
+EXPLAIN ANALYZE (PLAN) UPDATE a SET a = a*3 RETURNING a
+
+statement ok
+EXPLAIN ANALYZE (PLAN) UPSERT INTO a VALUES(10)
+
+statement ok
+EXPLAIN ANALYZE (PLAN) SELECT (SELECT 1);
+
+statement ok
+EXPLAIN ANALYZE (PLAN) DELETE FROM a
+
+statement ok
+EXPLAIN ANALYZE (PLAN) DROP TABLE a
+
 # Tests with EXPLAIN ANALYZE and subqueries.
 
 statement ok

pkg/sql/logictest/testdata/logic_test/explain_analyze_plans

@@ -1,4 +1,4 @@
-# LogicTest: 5node 5node-spec-planning
+# LogicTest: 5node
 
 # These tests are different from explain_analyze because they require manual
 # data placement.
@@ -99,3 +99,18 @@ query T
 SELECT url FROM [EXPLAIN ANALYZE (DISTSQL) SELECT k FROM kv WHERE k = 0];
 ----
 https://cockroachdb.github.io/distsqlplan/decode.html#eJyMkE9r4zAQxe_7KYbZyy6oWL4KCklbl5q6SWqH_gs-KPaQGjuWKsmhIfi7F1uG0EOhx_ebN096c0L70aDALEqi6zV0poHbdPkAm-hllczjBcwX8-T1LYJ_N3G2zh6T_zBZa2-sD_B8F6UR1HAJPEeGrSppIfdkUWwwxJyhNqoga5UZ0Gk0xOUnCs6wanXnBpwzLJQhFCd0lWsIBa7ltqGUZEkm4MiwJCerZoytDzNtqr00R2SYadlaAQG_CHjwFxkuOydgFiLD-ydw1Z4EcDupTjdkwZAsBXDPtkd3RnCFDLfSFe9kQXVOD1mDcdo8o7xn6NX0f-vkjlCEPft9x5SsVq2lb_V-SuZ9zpDKHfk7WtWZglZGFeMzXi7HvRGUZJ2fhl7ErR_1ef_nKwAA__9iwp6v
+
+query T
+EXPLAIN ANALYZE (PLAN) SELECT k FROM kv WHERE k = 0
+----
+planning time: 10µs
+execution time: 100µs
+distribution: full
+vectorized: true
+·
+• scan
+  missing stats
+  table: kv@primary
+  spans: [/0 - /0]
+·
+WARNING: this statement is experimental!

pkg/sql/parser/parse_test.go

@@ -548,6 +548,7 @@ func TestParse(t *testing.T) {
 		{`EXPLAIN (OPT, VERBOSE) SELECT 1`},
 		{`EXPLAIN ANALYZE (DISTSQL) SELECT 1`},
 		{`EXPLAIN ANALYZE (DEBUG) SELECT 1`},
+		{`EXPLAIN ANALYZE (PLAN) SELECT 1`},
 		{`SELECT * FROM [EXPLAIN SELECT 1]`},
 		{`SELECT * FROM [SHOW TRANSACTION STATUS]`},
 

pkg/sql/parser/sql.y

@@ -3571,8 +3571,9 @@ analyze_target:
 // %Text:
 // EXPLAIN <statement>
 // EXPLAIN ([PLAN ,] <planoptions...> ) <statement>
-// EXPLAIN [ANALYZE] (DISTSQL) <statement>
+// EXPLAIN (DISTSQL) <statement>
 // EXPLAIN ANALYZE [(DISTSQL)] <statement>
+// EXPLAIN ANALYZE (PLAN <planoptions...>) <statement>
 //
 // Explainable statements:
 //     SELECT, CREATE, DROP, ALTER, INSERT, UPSERT, UPDATE, DELETE,

pkg/sql/parser/testdata/errors

@@ -524,14 +524,6 @@ EXPLAIN EXECUTE a
         ^
 HINT: try \h EXPLAIN
 
-error
-EXPLAIN ANALYZE (PLAN) SELECT 1
-----
-at or near "EOF": syntax error: EXPLAIN ANALYZE cannot be used with PLAN
-DETAIL: source SQL:
-EXPLAIN ANALYZE (PLAN) SELECT 1
-                               ^
-
 error
 EXPLAIN (ANALYZE, PLAN) SELECT 1
 ----

pkg/sql/sem/tree/explain.go

@@ -246,7 +246,7 @@ func MakeExplain(options []string, stmt Statement) (Statement, error) {
 	}
 
 	if analyze {
-		if opts.Mode != ExplainDistSQL && opts.Mode != ExplainDebug {
+		if opts.Mode != ExplainDistSQL && opts.Mode != ExplainDebug && opts.Mode != ExplainPlan {
 			return nil, pgerror.Newf(pgcode.Syntax, "EXPLAIN ANALYZE cannot be used with %s", opts.Mode)
 		}
 		return &ExplainAnalyze{