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

@@ -371,7 +371,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

@@ -827,6 +827,11 @@ 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.
+	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"
@@ -146,6 +147,7 @@ func (ih *instrumentationHelper) Setup(
 func (ih *instrumentationHelper) Finish(
 	cfg *ExecutorConfig,
 	appStats *appStats,
+	statsCollector *sqlStatsCollector,
 	p *planner,
 	ast tree.Statement,
 	stmtRawSQL string,
@@ -186,7 +188,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,19 +299,21 @@ func (ih *instrumentationHelper) planStringForBundle() string {
 
 // planRows 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) planRows(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.codec, ih.explainPlan, ih.distribution, ih.vectorized); err != nil {
 		return []string{fmt.Sprintf("error emitting plan: %v", err)}
 	}
 	return ob.BuildStringRows()
 }
 
 func (ih *instrumentationHelper) setExplainAnalyzePlanResult(
-	ctx context.Context, res RestrictedCommandResult,
+	ctx context.Context, res RestrictedCommandResult, phaseTimes *phaseTimes,
 ) error {
 	res.ResetStmtType(&tree.ExplainAnalyze{})
 	res.SetColumns(ctx, colinfo.ExplainPlanColumns)
@@ -315,7 +323,7 @@ func (ih *instrumentationHelper) setExplainAnalyzePlanResult(
 		return nil
 	}
 
-	rows := ih.planRows()
+	rows := ih.planRows(phaseTimes)
 	rows = append(rows, "")
 	rows = append(rows, "WARNING: this statement is experimental!")
 	for _, row := range rows {
@@ -325,3 +333,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/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"
@@ -1285,6 +1286,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#eJyMkE9rs0AYxO_vp3iY99LCFv
 query T
 EXPLAIN ANALYZE (PLAN) SELECT k FROM kv WHERE k = 0
 ----
+planning time: 10µs
+execution time: 100µs
 distribution: full
 vectorized: true
 ·