From 9ceeeb9b09f4432747849a285676433b8a7f0539 Mon Sep 17 00:00:00 2001 From: Radu Berinde Date: Tue, 10 Nov 2020 16:26:18 -0500 Subject: [PATCH] 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 | 3 +- pkg/sql/exec_util.go | 7 ++++ pkg/sql/instrumentation.go | 38 +++++++++++++++---- pkg/sql/logictest/BUILD.bazel | 1 + pkg/sql/logictest/logic.go | 4 ++ .../testdata/logic_test/explain_analyze_plans | 4 +- 6 files changed, 47 insertions(+), 10 deletions(-) diff --git a/pkg/sql/conn_executor_exec.go b/pkg/sql/conn_executor_exec.go index b136f446cf53..36c25260d1c6 100644 --- a/pkg/sql/conn_executor_exec.go +++ b/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 diff --git a/pkg/sql/exec_util.go b/pkg/sql/exec_util.go index 219ccb4357bb..9a4cac578f75 100644 --- a/pkg/sql/exec_util.go +++ b/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. diff --git a/pkg/sql/instrumentation.go b/pkg/sql/instrumentation.go index 46c22c83141f..29ebb080ba7e 100644 --- a/pkg/sql/instrumentation.go +++ b/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), +} diff --git a/pkg/sql/logictest/BUILD.bazel b/pkg/sql/logictest/BUILD.bazel index 3b96fcdb99d4..a1b3e1966f00 100644 --- a/pkg/sql/logictest/BUILD.bazel +++ b/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", diff --git a/pkg/sql/logictest/logic.go b/pkg/sql/logictest/logic.go index 547fe22f0e21..5b78f9d7b20d 100644 --- a/pkg/sql/logictest/logic.go +++ b/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", diff --git a/pkg/sql/logictest/testdata/logic_test/explain_analyze_plans b/pkg/sql/logictest/testdata/logic_test/explain_analyze_plans index 004e858a9dc8..86c1c1bc3d66 100644 --- a/pkg/sql/logictest/testdata/logic_test/explain_analyze_plans +++ b/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 ·