From 056d5c5fd6f37e02a586ad9e9b6cd9fd12d16b68 Mon Sep 17 00:00:00 2001 From: arulajmani Date: Tue, 23 Jun 2020 12:43:40 -0400 Subject: [PATCH] sql: add a new observer statement to show last query statistics Adds a new observer statement `SHOW LAST QUERY STATISTICS` which returns service, latency, planning, and parsing timigns for the last executed statement. By exposing these timings this PR builds a bridge towards providing more in-depth metrics to improve timings displayed by the CLI. Note that this new statement should probably not be exposed to users, and should only be used for internal use (and therefore I'm leaving the release note blank here). This is because the CLI issues some "under the hood" queries (eg. retriving the current db so that it can be displayed). If a user would use this statement without insight into these "under the hood" queries it could prove to be confusing. Informs #49450 Release note: none --- pkg/sql/conn_executor.go | 1 + pkg/sql/conn_executor_exec.go | 25 +++++++++- pkg/sql/conn_executor_test.go | 67 +++++++++++++++++++++++++++ pkg/sql/delegate/delegate.go | 6 +++ pkg/sql/exec_util.go | 11 +++-- pkg/sql/executor_statement_metrics.go | 36 +++++++++----- pkg/sql/parser/help_test.go | 1 + pkg/sql/parser/parse_test.go | 1 + pkg/sql/parser/sql.y | 15 +++++- pkg/sql/sem/tree/show.go | 8 ++++ pkg/sql/sem/tree/stmt.go | 9 ++++ pkg/sql/sqlbase/result_columns.go | 9 ++++ 12 files changed, 173 insertions(+), 16 deletions(-) diff --git a/pkg/sql/conn_executor.go b/pkg/sql/conn_executor.go index 08038168373b..b50d00767a52 100644 --- a/pkg/sql/conn_executor.go +++ b/pkg/sql/conn_executor.go @@ -1026,6 +1026,7 @@ type connExecutor struct { // safe to use when a statement is not being parallelized. It must be reset // before using. planner planner + // phaseTimes tracks session- and transaction-level phase times. It is // copied-by-value when resetting statsCollector before executing each // statement. diff --git a/pkg/sql/conn_executor_exec.go b/pkg/sql/conn_executor_exec.go index 8278ebb13dbc..acaf041266bf 100644 --- a/pkg/sql/conn_executor_exec.go +++ b/pkg/sql/conn_executor_exec.go @@ -31,6 +31,7 @@ import ( "github.com/cockroachdb/cockroach/pkg/sql/sqlbase" "github.com/cockroachdb/cockroach/pkg/sql/sqltelemetry" "github.com/cockroachdb/cockroach/pkg/sql/types" + "github.com/cockroachdb/cockroach/pkg/util/duration" "github.com/cockroachdb/cockroach/pkg/util/errorutil/unimplemented" "github.com/cockroachdb/cockroach/pkg/util/fsm" "github.com/cockroachdb/cockroach/pkg/util/hlc" @@ -69,6 +70,7 @@ func (ex *connExecutor) execStmt( // Run observer statements in a separate code path; their execution does not // depend on the current transaction state. if _, ok := stmt.AST.(tree.ObserverStatement); ok { + ex.statsCollector.reset(&ex.server.sqlStats, ex.appStats, &ex.phaseTimes) err := ex.runObserverStatement(ctx, stmt, res) // Note that regardless of res.Err(), these observer statements don't // generate error events; transactions are always allowed to continue. @@ -493,7 +495,6 @@ func (ex *connExecutor) execStmtInOpenState( } p.extendedEvalCtx.Placeholders = &p.semaCtx.Placeholders p.extendedEvalCtx.Annotations = &p.semaCtx.Annotations - ex.phaseTimes[plannerStartExecStmt] = timeutil.Now() p.stmt = &stmt p.cancelChecker = sqlbase.NewCancelChecker(ctx) p.autoCommit = os.ImplicitTxn.Get() && !ex.server.cfg.TestingKnobs.DisableAutoCommit @@ -1117,6 +1118,8 @@ func (ex *connExecutor) runObserverStatement( case *tree.SetTracing: ex.runSetTracing(ctx, sqlStmt, res) return nil + case *tree.ShowLastQueryStatistics: + return ex.runShowLastQueryStatistics(ctx, res) default: res.SetError(errors.AssertionFailedf("unrecognized observer statement type %T", stmt.AST)) return nil @@ -1154,6 +1157,26 @@ func (ex *connExecutor) runShowTransactionState( return res.AddRow(ctx, tree.Datums{tree.NewDString(state)}) } +func (ex *connExecutor) runShowLastQueryStatistics( + ctx context.Context, res RestrictedCommandResult, +) error { + res.SetColumns(ctx, sqlbase.ShowLastQueryStatisticsColumns) + + phaseTimes := &ex.statsCollector.previousPhaseTimes + runLat := phaseTimes.getRunLatency().Seconds() + parseLat := phaseTimes.getParsingLatency().Seconds() + planLat := phaseTimes.getPlanningLatency().Seconds() + svcLat := phaseTimes.getServiceLatency().Seconds() + + return res.AddRow(ctx, + tree.Datums{ + tree.NewDInterval(duration.FromFloat64(parseLat), types.DefaultIntervalTypeMetadata), + tree.NewDInterval(duration.FromFloat64(planLat), types.DefaultIntervalTypeMetadata), + tree.NewDInterval(duration.FromFloat64(runLat), types.DefaultIntervalTypeMetadata), + tree.NewDInterval(duration.FromFloat64(svcLat), types.DefaultIntervalTypeMetadata), + }) +} + func (ex *connExecutor) runSetTracing( ctx context.Context, n *tree.SetTracing, res RestrictedCommandResult, ) { diff --git a/pkg/sql/conn_executor_test.go b/pkg/sql/conn_executor_test.go index 77f888abe6b2..3839a670e3f7 100644 --- a/pkg/sql/conn_executor_test.go +++ b/pkg/sql/conn_executor_test.go @@ -34,6 +34,7 @@ import ( "github.com/cockroachdb/cockroach/pkg/sql/pgwire/pgcode" "github.com/cockroachdb/cockroach/pkg/sql/row" "github.com/cockroachdb/cockroach/pkg/sql/rowexec" + "github.com/cockroachdb/cockroach/pkg/sql/sem/tree" "github.com/cockroachdb/cockroach/pkg/sql/tests" "github.com/cockroachdb/cockroach/pkg/testutils" "github.com/cockroachdb/cockroach/pkg/testutils/serverutils" @@ -811,6 +812,72 @@ func TestTrimFlushedStatements(t *testing.T) { require.NoError(t, tx.Commit()) } +func TestShowLastQueryStatistics(t *testing.T) { + defer leaktest.AfterTest(t)() + + ctx := context.Background() + params := base.TestServerArgs{} + s, sqlConn, _ := serverutils.StartServer(t, params) + defer s.Stopper().Stop(ctx) + + if _, err := sqlConn.Exec("CREATE TABLE t(a INT)"); err != nil { + t.Fatal(err) + } + + rows, err := sqlConn.Query("SHOW LAST QUERY STATISTICS") + if err != nil { + t.Fatalf("show last query statistics failed: %v", err) + } + defer rows.Close() + + var parseLatency string + var planLatency string + var execLatency string + var serviceLatency string + + rows.Next() + if err := rows.Scan(&parseLatency, &planLatency, &execLatency, &serviceLatency); err != nil { + t.Fatalf("unexpected error while reading last query statistics: %v", err) + } + + parseInterval, err := tree.ParseDInterval(parseLatency) + if err != nil { + t.Fatal(err) + } + planInterval, err := tree.ParseDInterval(planLatency) + if err != nil { + t.Fatal(err) + } + execInterval, err := tree.ParseDInterval(execLatency) + if err != nil { + t.Fatal(err) + } + serviceInterval, err := tree.ParseDInterval(serviceLatency) + if err != nil { + t.Fatal(err) + } + + if parseInterval.AsFloat64() <= 0 || parseInterval.AsFloat64() > 1 { + t.Fatalf("unexpected parse latency: %v", parseInterval.AsFloat64()) + } + + if planInterval.AsFloat64() <= 0 || planInterval.AsFloat64() > 1 { + t.Fatalf("unexpected plan latency: %v", planInterval.AsFloat64()) + } + + if serviceInterval.AsFloat64() <= 0 || serviceInterval.AsFloat64() > 1 { + t.Fatalf("unexpected service latency: %v", serviceInterval.AsFloat64()) + } + + if execInterval.AsFloat64() <= 0 || execInterval.AsFloat64() > 1 { + t.Fatalf("unexpected execution latency: %v", execInterval.AsFloat64()) + } + + if rows.Next() { + t.Fatalf("unexpected number of rows returned by last query statistics: %v", err) + } +} + // dynamicRequestFilter exposes a filter method which is a // kvserverbase.ReplicaRequestFilter but can be set dynamically. type dynamicRequestFilter struct { diff --git a/pkg/sql/delegate/delegate.go b/pkg/sql/delegate/delegate.go index 0f5dc665e53d..b6e81d4de597 100644 --- a/pkg/sql/delegate/delegate.go +++ b/pkg/sql/delegate/delegate.go @@ -109,6 +109,12 @@ func TryDelegate( case *tree.ShowTransactionStatus: return d.delegateShowVar(&tree.ShowVar{Name: "transaction_status"}) + case *tree.ShowLastQueryStatistics: + return nil, unimplemented.New( + "show last query statistics", + "cannot use SHOW LAST QUERY STATISTICS as a statement source", + ) + case *tree.ShowSavepointStatus: return nil, unimplemented.NewWithIssue(47333, "cannot use SHOW SAVEPOINT STATUS as a statement source") diff --git a/pkg/sql/exec_util.go b/pkg/sql/exec_util.go index ffb29b947116..a44730c9b355 100644 --- a/pkg/sql/exec_util.go +++ b/pkg/sql/exec_util.go @@ -2144,6 +2144,9 @@ type sqlStatsCollector struct { appStats *appStats // phaseTimes tracks session-level phase times. phaseTimes phaseTimes + // previousPhaseTimes tracks the session-level phase times for the previous + // query. This enables the `SHOW LAST QUERY STATISTICS` observer statement. + previousPhaseTimes phaseTimes } // newSQLStatsCollector creates an instance of sqlStatsCollector. Note that @@ -2185,9 +2188,11 @@ func (s *sqlStatsCollector) recordTransaction(txnTimeSec float64, ev txnEvent, i } func (s *sqlStatsCollector) reset(sqlStats *sqlStats, appStats *appStats, phaseTimes *phaseTimes) { + previousPhaseTimes := &s.phaseTimes *s = sqlStatsCollector{ - sqlStats: sqlStats, - appStats: appStats, - phaseTimes: *phaseTimes, + sqlStats: sqlStats, + appStats: appStats, + previousPhaseTimes: *previousPhaseTimes, + phaseTimes: *phaseTimes, } } diff --git a/pkg/sql/executor_statement_metrics.go b/pkg/sql/executor_statement_metrics.go index 3e42016be3b7..35f56225f922 100644 --- a/pkg/sql/executor_statement_metrics.go +++ b/pkg/sql/executor_statement_metrics.go @@ -58,6 +58,27 @@ const ( // copy behavior. type phaseTimes [sessionNumPhases]time.Time +// getServiceLatency returns the time between a query being received and the end +// of run. +func (p *phaseTimes) getServiceLatency() time.Duration { + return p[plannerEndExecStmt].Sub(p[sessionQueryReceived]) +} + +// getRunLatency returns the time between a query execution starting and ending. +func (p *phaseTimes) getRunLatency() time.Duration { + return p[plannerEndExecStmt].Sub(p[plannerStartExecStmt]) +} + +// getPlanningLatency returns the time it takes for a query to be planned. +func (p *phaseTimes) getPlanningLatency() time.Duration { + return p[plannerEndLogicalPlan].Sub(p[plannerStartLogicalPlan]) +} + +// getParsingLatency returns the time it takes for a query to be parsed. +func (p *phaseTimes) getParsingLatency() time.Duration { + return p[sessionEndParse].Sub(p[sessionStartParse]) +} + // EngineMetrics groups a set of SQL metrics. type EngineMetrics struct { // The subset of SELECTs that are processed through DistSQL. @@ -108,19 +129,12 @@ func (ex *connExecutor) recordStatementSummary( ) { phaseTimes := &ex.statsCollector.phaseTimes - // Compute the run latency. This is always recorded in the - // server metrics. - runLatRaw := phaseTimes[plannerEndExecStmt].Sub(phaseTimes[plannerStartExecStmt]) - // Collect the statistics. + runLatRaw := phaseTimes.getRunLatency() runLat := runLatRaw.Seconds() - - parseLat := phaseTimes[sessionEndParse]. - Sub(phaseTimes[sessionStartParse]).Seconds() - planLat := phaseTimes[plannerEndLogicalPlan]. - Sub(phaseTimes[plannerStartLogicalPlan]).Seconds() - // service latency: time query received to end of run - svcLatRaw := phaseTimes[plannerEndExecStmt].Sub(phaseTimes[sessionQueryReceived]) + parseLat := phaseTimes.getParsingLatency().Seconds() + planLat := phaseTimes.getPlanningLatency().Seconds() + svcLatRaw := phaseTimes.getServiceLatency() svcLat := svcLatRaw.Seconds() // processing latency: contributing towards SQL results. diff --git a/pkg/sql/parser/help_test.go b/pkg/sql/parser/help_test.go index 20a22e29eb58..95806569ba24 100644 --- a/pkg/sql/parser/help_test.go +++ b/pkg/sql/parser/help_test.go @@ -320,6 +320,7 @@ func TestContextualHelp(t *testing.T) { {`SHOW SYNTAX ??`, `SHOW SYNTAX`}, {`SHOW SYNTAX 'foo' ??`, `SHOW SYNTAX`}, {`SHOW SAVEPOINT STATUS ??`, `SHOW SAVEPOINT`}, + {`SHOW LAST QUERY STATISTICS ??`, `SHOW LAST QUERY STATISTICS`}, {`SHOW RANGE ??`, `SHOW RANGE`}, diff --git a/pkg/sql/parser/parse_test.go b/pkg/sql/parser/parse_test.go index 1bcd67af49da..f27b804a8d20 100644 --- a/pkg/sql/parser/parse_test.go +++ b/pkg/sql/parser/parse_test.go @@ -572,6 +572,7 @@ func TestParse(t *testing.T) { {`EXPLAIN SHOW TRANSACTION STATUS`}, {`SHOW SAVEPOINT STATUS`}, {`EXPLAIN SHOW SAVEPOINT STATUS`}, + {`SHOW LAST QUERY STATISTICS`}, {`SHOW SYNTAX 'select 1'`}, {`EXPLAIN SHOW SYNTAX 'select 1'`}, diff --git a/pkg/sql/parser/sql.y b/pkg/sql/parser/sql.y index bbd50a7b9b7d..5dd9086796b1 100644 --- a/pkg/sql/parser/sql.y +++ b/pkg/sql/parser/sql.y @@ -822,6 +822,7 @@ func (u *sqlSymUnion) alterTypeAddValuePlacement() *tree.AlterTypeAddValuePlacem %type show_savepoint_stmt %type show_stats_stmt %type show_syntax_stmt +%type show_last_query_stats_stmt %type show_tables_stmt %type show_trace_stmt %type show_transaction_stmt @@ -3668,7 +3669,8 @@ zone_value: // SHOW CREATE, SHOW DATABASES, SHOW HISTOGRAM, SHOW INDEXES, SHOW // PARTITIONS, SHOW JOBS, SHOW QUERIES, SHOW RANGE, SHOW RANGES, // SHOW ROLES, SHOW SCHEMAS, SHOW SEQUENCES, SHOW SESSION, SHOW SESSIONS, -// SHOW STATISTICS, SHOW SYNTAX, SHOW TABLES, SHOW TRACE SHOW TRANSACTION, SHOW USERS +// SHOW STATISTICS, SHOW SYNTAX, SHOW TABLES, SHOW TRACE SHOW TRANSACTION, SHOW USERS, +// SHOW LAST QUERY STATISTICS show_stmt: show_backup_stmt // EXTEND WITH HELP: SHOW BACKUP | show_columns_stmt // EXTEND WITH HELP: SHOW COLUMNS @@ -3699,6 +3701,7 @@ show_stmt: | show_users_stmt // EXTEND WITH HELP: SHOW USERS | show_zone_stmt | SHOW error // SHOW HELP: SHOW +| show_last_query_stats_stmt // EXTEND WITH HELP: SHOW LAST QUERY STATISTICS // Cursors are not yet supported by CockroachDB. CLOSE ALL is safe to no-op // since there will be no open cursors. @@ -4170,6 +4173,16 @@ show_syntax_stmt: } | SHOW SYNTAX error // SHOW HELP: SHOW SYNTAX +// %Help: SHOW LAST QUERY STATISTICS - display statistics for the last query issued +// %Category: Misc +// %Text: SHOW LAST QUERY STATISTICS +show_last_query_stats_stmt: + SHOW LAST QUERY STATISTICS + { + /* SKIP DOC */ + $$.val = &tree.ShowLastQueryStatistics{} + } + // %Help: SHOW SAVEPOINT - display current savepoint properties // %Category: Cfg // %Text: SHOW SAVEPOINT STATUS diff --git a/pkg/sql/sem/tree/show.go b/pkg/sql/sem/tree/show.go index e1a62775ae7d..f90ab30af4ef 100644 --- a/pkg/sql/sem/tree/show.go +++ b/pkg/sql/sem/tree/show.go @@ -395,6 +395,14 @@ func (node *ShowTransactionStatus) Format(ctx *FmtCtx) { ctx.WriteString("SHOW TRANSACTION STATUS") } +// ShowLastQueryStatistics represents a SHOW LAST QUERY STATS statement. +type ShowLastQueryStatistics struct{} + +// Format implements the NodeFormatter interface. +func (node *ShowLastQueryStatistics) Format(ctx *FmtCtx) { + ctx.WriteString("SHOW LAST QUERY STATISTICS") +} + // ShowSavepointStatus represents a SHOW SAVEPOINT STATUS statement. type ShowSavepointStatus struct { } diff --git a/pkg/sql/sem/tree/stmt.go b/pkg/sql/sem/tree/stmt.go index 25953c70bd65..5678a9162ada 100644 --- a/pkg/sql/sem/tree/stmt.go +++ b/pkg/sql/sem/tree/stmt.go @@ -811,6 +811,14 @@ func (*ShowSavepointStatus) StatementTag() string { return "SHOW SAVEPOINT STATU func (*ShowSavepointStatus) observerStatement() {} +// StatementType implements the Statement interface. +func (*ShowLastQueryStatistics) StatementType() StatementType { return Rows } + +// StatementTag returns a short string identifying the type of statement. +func (*ShowLastQueryStatistics) StatementTag() string { return "SHOW LAST QUERY STATISTICS" } + +func (*ShowLastQueryStatistics) observerStatement() {} + // StatementType implements the Statement interface. func (*ShowUsers) StatementType() StatementType { return Rows } @@ -1016,6 +1024,7 @@ func (n *ShowTableStats) String() string { return AsString(n) } func (n *ShowTables) String() string { return AsString(n) } func (n *ShowTraceForSession) String() string { return AsString(n) } func (n *ShowTransactionStatus) String() string { return AsString(n) } +func (n *ShowLastQueryStatistics) String() string { return AsString(n) } func (n *ShowUsers) String() string { return AsString(n) } func (n *ShowVar) String() string { return AsString(n) } func (n *ShowZoneConfig) String() string { return AsString(n) } diff --git a/pkg/sql/sqlbase/result_columns.go b/pkg/sql/sqlbase/result_columns.go index 223fef93f65c..baabca350f00 100644 --- a/pkg/sql/sqlbase/result_columns.go +++ b/pkg/sql/sqlbase/result_columns.go @@ -206,6 +206,15 @@ var ShowSyntaxColumns = ResultColumns{ {Name: "message", Typ: types.String}, } +// ShowLastQueryStatisticsColumns are the columns of a +// SHOW LAST QUERY STATISTICS statement. +var ShowLastQueryStatisticsColumns = ResultColumns{ + {Name: "parse_latency", Typ: types.Interval}, + {Name: "plan_latency", Typ: types.Interval}, + {Name: "exec_latency", Typ: types.Interval}, + {Name: "service_latency", Typ: types.Interval}, +} + // ShowFingerprintsColumns are the result columns of a // SHOW EXPERIMENTAL_FINGERPRINTS statement. var ShowFingerprintsColumns = ResultColumns{