diff --git a/pkg/sql/conn_executor_exec.go b/pkg/sql/conn_executor_exec.go index 82c933692584..36c25260d1c6 100644 --- a/pkg/sql/conn_executor_exec.go +++ b/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 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/explain_tree_test.go b/pkg/sql/explain_tree_test.go index b25cfd6c8ac9..41084bb5c373 100644 --- a/pkg/sql/explain_tree_test.go +++ b/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 { diff --git a/pkg/sql/instrumentation.go b/pkg/sql/instrumentation.go index 25b7d039fcee..29ebb080ba7e 100644 --- a/pkg/sql/instrumentation.go +++ b/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), +} 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 b/pkg/sql/logictest/testdata/logic_test/explain_analyze index c4767b0a9729..19c777a5bfec 100644 --- a/pkg/sql/logictest/testdata/logic_test/explain_analyze +++ b/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 diff --git a/pkg/sql/logictest/testdata/logic_test/explain_analyze_plans b/pkg/sql/logictest/testdata/logic_test/explain_analyze_plans index b5858a278f23..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. @@ -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! diff --git a/pkg/sql/parser/parse_test.go b/pkg/sql/parser/parse_test.go index 22420c8deb5f..009f536bc9fe 100644 --- a/pkg/sql/parser/parse_test.go +++ b/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]`}, diff --git a/pkg/sql/parser/sql.y b/pkg/sql/parser/sql.y index d1b35dfee8bb..d11cfae310c8 100644 --- a/pkg/sql/parser/sql.y +++ b/pkg/sql/parser/sql.y @@ -3571,8 +3571,9 @@ analyze_target: // %Text: // EXPLAIN // EXPLAIN ([PLAN ,] ) -// EXPLAIN [ANALYZE] (DISTSQL) +// EXPLAIN (DISTSQL) // EXPLAIN ANALYZE [(DISTSQL)] +// EXPLAIN ANALYZE (PLAN ) // // Explainable statements: // SELECT, CREATE, DROP, ALTER, INSERT, UPSERT, UPDATE, DELETE, diff --git a/pkg/sql/parser/testdata/errors b/pkg/sql/parser/testdata/errors index 2a485b40b536..e8d304fc71f0 100644 --- a/pkg/sql/parser/testdata/errors +++ b/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 ---- diff --git a/pkg/sql/sem/tree/explain.go b/pkg/sql/sem/tree/explain.go index 781d3338cc7d..b85366273557 100644 --- a/pkg/sql/sem/tree/explain.go +++ b/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{