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

pkg/sql/conn_executor_exec.go

@@ -348,6 +348,7 @@ func (ex *connExecutor) execStmtInOpenState(
 			telemetry.Inc(sqltelemetry.ExplainAnalyzeDebugUseCounter)
 			ih.SetOutputMode(explainAnalyzeDebugOutput, explain.Flags{})
 		} else {
+			telemetry.Inc(sqltelemetry.ExplainAnalyzeUseCounter)
 			flags := explain.MakeFlags(&e.ExplainOptions)
 			ih.SetOutputMode(explainAnalyzePlanOutput, flags)
 		}
@@ -371,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/instrumentation.go

@@ -13,6 +13,7 @@ package sql
 import (
 	"context"
 	"fmt"
+	"time"
 
 	"github.com/cockroachdb/cockroach/pkg/keys"
 	"github.com/cockroachdb/cockroach/pkg/roachpb"
@@ -148,6 +149,7 @@ func (ih *instrumentationHelper) Setup(
 func (ih *instrumentationHelper) Finish(
 	cfg *ExecutorConfig,
 	appStats *appStats,
+	statsCollector *sqlStatsCollector,
 	p *planner,
 	ast tree.Statement,
 	stmtRawSQL string,
@@ -188,7 +190,11 @@ func (ih *instrumentationHelper) Finish(
 	}
 
 	if ih.outputMode == explainAnalyzePlanOutput && retErr == nil {
-		retErr = ih.setExplainAnalyzePlanResult(ctx, res)
+		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.
@@ -293,31 +299,37 @@ func (ih *instrumentationHelper) planStringForBundle() string {
 	return ob.BuildString()
 }
 
-// planRows generates the plan tree as a list of strings (one for each line).
+// planRowsForExplainAnalyze generates the plan tree as a list of strings (one
+// for each line).
 // Used in explainAnalyzePlanOutput mode.
-func (ih *instrumentationHelper) planRows() []string {
+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,
-) error {
+	ctx context.Context, res RestrictedCommandResult, phaseTimes *phaseTimes,
+) (commErr error) {
 	res.ResetStmtType(&tree.ExplainAnalyze{})
 	res.SetColumns(ctx, colinfo.ExplainPlanColumns)
 
-	if err := res.Err(); err != nil {
+	if res.Err() != nil {
 		// Can't add rows if there was an error.
-		return nil
+		return nil //nolint:returnerrcheck
 	}
 
-	rows := ih.planRows()
+	rows := ih.planRowsForExplainAnalyze(phaseTimes)
 	rows = append(rows, "")
 	rows = append(rows, "WARNING: this statement is experimental!")
 	for _, row := range rows {
@@ -327,3 +339,13 @@ func (ih *instrumentationHelper) setExplainAnalyzePlanResult(
 	}
 	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_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.
@@ -103,6 +103,8 @@ https://cockroachdb.github.io/distsqlplan/decode.html#eJyMkE9r4zAQxe_7KYbZyy6oWL
 query T
 EXPLAIN ANALYZE (PLAN) SELECT k FROM kv WHERE k = 0
 ----
+planning time: 10µs
+execution time: 100µs
 distribution: full
 vectorized: true
 ·