From 531568571f5abc4da638e848116f2533409eb299 Mon Sep 17 00:00:00 2001 From: arulajmani Date: Sun, 2 Aug 2020 22:30:06 -0400 Subject: [PATCH] cli: improve interactive sql shell timings Previously, the CLI displayed timings by timing a query on the client. This would include both the client-server latency and the query execution time, without bucketing which is what. This patch changes this by switching the way we calculate timings in the CLI. Instead of timing on the client, we now send a `SHOW LAST QUERY STATISTICS` query after a statement is executed. This allows us to display both the network latency and the network latency as separate values. Additionally, this patch no longer displays timings for queries that include multiple statements on one line. This is to mitigate #48180, where timings for executing all the statements are incorrectly attributed to the first statement. Actually fixing the issue is beyond the scope of this PR. Fixes #49450 Release note (cli change): The CLI no longer prints a blanket `Time` for queries. Instead, if `show_times` is turned on and the server version is >=20.2, the CLI prints two separate times -- the server execution time and the network latency. Release justification: low risk, high benefit change to existing functionality. --- pkg/cli/context.go | 4 + .../test_client_side_checking.tcl | 2 +- .../interactive_tests/test_error_handling.tcl | 8 -- pkg/cli/interactive_tests/test_notice.tcl | 2 +- pkg/cli/interactive_tests/test_timing.tcl | 34 +++++ pkg/cli/interactive_tests/test_txn_prompt.tcl | 2 +- pkg/cli/sql.go | 39 +++--- pkg/cli/sql_util.go | 121 +++++++++++++++--- pkg/sql/parser/parse.go | 18 +++ 9 files changed, 179 insertions(+), 51 deletions(-) create mode 100644 pkg/cli/interactive_tests/test_timing.tcl diff --git a/pkg/cli/context.go b/pkg/cli/context.go index 78050ec038e6..47ce27b9b010 100644 --- a/pkg/cli/context.go +++ b/pkg/cli/context.go @@ -217,6 +217,9 @@ var sqlCtx = struct { // "intelligent behavior" in the SQL shell as possible and become // more verbose (sets echo). debugMode bool + + // Determines whether to display server execution timings in the CLI. + enableServerExecutionTimings bool }{cliContext: &cliCtx} // setSQLContextDefaults set the default values in sqlCtx. This @@ -230,6 +233,7 @@ func setSQLContextDefaults() { sqlCtx.showTimes = false sqlCtx.debugMode = false sqlCtx.echo = false + sqlCtx.enableServerExecutionTimings = false } // zipCtx captures the command-line parameters of the `zip` command. diff --git a/pkg/cli/interactive_tests/test_client_side_checking.tcl b/pkg/cli/interactive_tests/test_client_side_checking.tcl index 3f1e58b0483a..ec5169cdd5d2 100644 --- a/pkg/cli/interactive_tests/test_client_side_checking.tcl +++ b/pkg/cli/interactive_tests/test_client_side_checking.tcl @@ -28,7 +28,7 @@ end_test start_test "Check that the syntax checker does not get confused by empty inputs." # (issue #22441.) send ";\r" -eexpect "0 rows" +eexpect "\n" eexpect root@ end_test diff --git a/pkg/cli/interactive_tests/test_error_handling.tcl b/pkg/cli/interactive_tests/test_error_handling.tcl index 1d1169df464e..fb45cc32750c 100644 --- a/pkg/cli/interactive_tests/test_error_handling.tcl +++ b/pkg/cli/interactive_tests/test_error_handling.tcl @@ -8,14 +8,6 @@ spawn /bin/bash send "PS1=':''/# '\r" eexpect ":/# " -start_test "Check that by default, an error prevents subsequent statements from running." -send "(echo 'select foo;'; echo 'select 1;') | $argv sql\r" -eexpect "ERROR: column \"foo\" does not exist" -eexpect ":/# " -send "echo \$?\r" -eexpect "1\r\n:/# " -end_test - start_test "Check that a user can request to continue upon failures." send "(echo '\\unset errexit'; echo 'select foo;'; echo 'select 1;') | $argv sql\r" eexpect "ERROR: column \"foo\" does not exist" diff --git a/pkg/cli/interactive_tests/test_notice.tcl b/pkg/cli/interactive_tests/test_notice.tcl index 7951b2acfa02..ffb5ee7b950c 100644 --- a/pkg/cli/interactive_tests/test_notice.tcl +++ b/pkg/cli/interactive_tests/test_notice.tcl @@ -21,8 +21,8 @@ send "SELECT crdb_internal.notice('hello') AS STAGE1;" send "SELECT crdb_internal.notice('world') AS STAGE2;\r" send "SELECT crdb_internal.notice('warning', 'stay indoors') AS STAGE3;\r" eexpect stage1 -eexpect stage2 eexpect "NOTICE: hello" +eexpect stage2 eexpect "NOTICE: world" eexpect "WARNING: stay indoors" eexpect root@ diff --git a/pkg/cli/interactive_tests/test_timing.tcl b/pkg/cli/interactive_tests/test_timing.tcl new file mode 100644 index 000000000000..d402bccb8db9 --- /dev/null +++ b/pkg/cli/interactive_tests/test_timing.tcl @@ -0,0 +1,34 @@ +#! /usr/bin/env expect -f + +source [file join [file dirname $argv0] common.tcl] + +# This test ensures timing displayed in the CLI works as expected. + +spawn $argv demo movr +eexpect root@ + +start_test "Test that server execution time and network latency are printed by default." +send "SELECT * FROM vehicles LIMIT 1;\r" +eexpect "1 row" +eexpect "Server Execution Time:" +eexpect "Network Latency:" + +# Ditto with multiple statements on one line +send "SELECT * FROM vehicles LIMIT 1; CREATE TABLE t(a int);\r" +eexpect "1 row" +eexpect "Server Execution Time:" +eexpect "Network Latency:" +eexpect "CREATE TABLE" +eexpect "Server Execution Time:" +eexpect "Network Latency:" +end_test + +start_test "Test show_server_execution_times works correctly" +send "\\set show_server_execution_times=false\r" +send "SELECT * FROM vehicles LIMIT 1;\r" +eexpect "\nTime:" +send "\\set show_server_execution_times=true\r" +send "SELECT * FROM vehicles LIMIT 1;\r" +eexpect "Server Execution Time:" +eexpect "Network Latency:" +end_test diff --git a/pkg/cli/interactive_tests/test_txn_prompt.tcl b/pkg/cli/interactive_tests/test_txn_prompt.tcl index af0382c94bac..831aa2b100ab 100644 --- a/pkg/cli/interactive_tests/test_txn_prompt.tcl +++ b/pkg/cli/interactive_tests/test_txn_prompt.tcl @@ -58,7 +58,7 @@ end_test start_test "Check option to echo statements" send "\\set echo\r" send "select 1;\r" -eexpect "\n> select 1;\r\n" +eexpect "\n> select 1\r\n" eexpect root@ end_test diff --git a/pkg/cli/sql.go b/pkg/cli/sql.go index a93aad8ad3f6..2a5c19c2d5ba 100644 --- a/pkg/cli/sql.go +++ b/pkg/cli/sql.go @@ -155,7 +155,8 @@ type cliState struct { partialStmtsLen int // concatLines is the concatenation of partialLines, computed during - // doCheckStatement and then reused in doRunStatement(). + // doPrepareStatementLine and then reused in doRunStatements() and + // doCheckStatement(). concatLines string // exitErr defines the error to report to the user upon termination. @@ -347,7 +348,7 @@ var options = map[string]struct { display: func(c *cliState) string { return strconv.FormatBool(c.errExit) }, }, `check_syntax`: { - description: "check the SQL syntax before running a query (needs SHOW SYNTAX support on the server)", + description: "check the SQL syntax before running a query", isBoolean: true, validDuringMultilineEntry: false, set: func(c *cliState, _ string) error { c.checkSyntax = true; return nil }, @@ -362,6 +363,14 @@ var options = map[string]struct { reset: func(_ *cliState) error { sqlCtx.showTimes = false; return nil }, display: func(_ *cliState) string { return strconv.FormatBool(sqlCtx.showTimes) }, }, + `show_server_execution_times`: { + description: "display the server execution times for queries (requires show_times to be set)", + isBoolean: true, + validDuringMultilineEntry: true, + set: func(_ *cliState, _ string) error { sqlCtx.enableServerExecutionTimings = true; return nil }, + reset: func(_ *cliState) error { sqlCtx.enableServerExecutionTimings = false; return nil }, + display: func(_ *cliState) string { return strconv.FormatBool(sqlCtx.enableServerExecutionTimings) }, + }, `smart_prompt`: { description: "deprecated", isBoolean: true, @@ -1140,7 +1149,7 @@ func (c *cliState) doCheckStatement(startState, contState, execState cliStateEnu fmt.Println(helpText) } - _ = c.invalidSyntax(0, "statement ignored: %v", + _ = c.invalidSyntax(cliStart, "statement ignored: %v", &formattedError{err: err, showSeverity: false, verbose: false}) // Stop here if exiterr is set. @@ -1168,7 +1177,9 @@ func (c *cliState) doCheckStatement(startState, contState, execState cliStateEnu return nextState } -func (c *cliState) doRunStatement(nextState cliStateEnum) cliStateEnum { +// doRunStatements runs all the statements that have been accumulated by +// concatLines. +func (c *cliState) doRunStatements(nextState cliStateEnum) cliStateEnum { // Once we send something to the server, the txn status may change arbitrarily. // Clear the known state so that further entries do not assume anything. c.lastKnownTxnStatus = " ?" @@ -1180,9 +1191,6 @@ func (c *cliState) doRunStatement(nextState cliStateEnum) cliStateEnum { c.exitErr = c.conn.Exec("SET tracing = off; SET tracing = "+c.autoTrace, nil) if c.exitErr != nil { cliOutputError(stderr, c.exitErr, true /*showSeverity*/, false /*verbose*/) - if c.errExit { - return cliStop - } return nextState } } @@ -1304,7 +1312,7 @@ func runInteractive(conn *sqlConn) (exitErr error) { state = c.doCheckStatement(cliStartLine, cliContinueLine, cliRunStatement) case cliRunStatement: - state = c.doRunStatement(cliStartLine) + state = c.doRunStatements(cliStartLine) default: panic(fmt.Sprintf("unknown state: %d", state)) @@ -1335,7 +1343,7 @@ func (c *cliState) configurePreShellDefaults() (cleanupFn func(), err error) { if !sqlCtx.debugMode { // Also, try to enable syntax checking if supported by the server. // This is a form of client-side error checking to help with large txns. - c.tryEnableCheckSyntax() + c.checkSyntax = true } } else { // When running non-interactive, by default we want errors to stop @@ -1418,7 +1426,7 @@ func (c *cliState) configurePreShellDefaults() (cleanupFn func(), err error) { return cleanupFn, nil } -// runOneStatement executes one statement and terminates +// runStatements executes the given statements and terminates // on error. func (c *cliState) runStatements(stmts []string) error { for { @@ -1525,17 +1533,6 @@ func setupSafeUpdates(cmd *cobra.Command, conn *sqlConn) { } } -// tryEnableCheckSyntax attempts to enable check_syntax. -// The option is enabled if the SHOW SYNTAX statement is recognized -// by the server. -func (c *cliState) tryEnableCheckSyntax() { - if err := c.conn.Exec("SHOW SYNTAX 'SHOW SYNTAX ''1'';'", nil); err != nil { - fmt.Fprintf(stderr, "warning: cannot enable check_syntax: %v\n", err) - } else { - c.checkSyntax = true - } -} - // serverSideParse uses the SHOW SYNTAX statement to analyze the given string. // If the syntax is correct, the function returns the statement // decomposition in the first return value. If it is not, the function diff --git a/pkg/cli/sql_util.go b/pkg/cli/sql_util.go index a53cf4a8bdc7..99bc11f144ae 100644 --- a/pkg/cli/sql_util.go +++ b/pkg/cli/sql_util.go @@ -29,6 +29,7 @@ import ( "github.com/cockroachdb/cockroach/pkg/security" "github.com/cockroachdb/cockroach/pkg/sql/catalog/catconstants" "github.com/cockroachdb/cockroach/pkg/sql/lex" + "github.com/cockroachdb/cockroach/pkg/sql/parser" "github.com/cockroachdb/cockroach/pkg/sql/sem/tree" "github.com/cockroachdb/cockroach/pkg/util/envutil" "github.com/cockroachdb/cockroach/pkg/util/log" @@ -170,6 +171,19 @@ func (c *sqlConn) ensureConn() error { return nil } +// tryEnableServerExecutionTimings attempts to check if the server supports the +// SHOW LAST QUERY STATISTICS statements. This allows the CLI client to report +// server side execution timings instead of timing on the client. +func (c *sqlConn) tryEnableServerExecutionTimings() { + _, _, err := c.getLastQueryStatistics() + if err != nil { + fmt.Fprintf(stderr, "warning: cannot show server execution timings: unexpected column found\n") + sqlCtx.enableServerExecutionTimings = false + } else { + sqlCtx.enableServerExecutionTimings = true + } +} + func (c *sqlConn) getServerMetadata() ( nodeID roachpb.NodeID, version, clusterID string, @@ -299,6 +313,9 @@ func (c *sqlConn) checkServerMetadata() error { fmt.Println("# Organization:", c.clusterOrganization) } } + // Try to enable server execution timings for the CLI to display if + // supported by the server. + c.tryEnableServerExecutionTimings() return nil } @@ -325,8 +342,6 @@ func (c *sqlConn) requireServerVersion(required *version.Version) error { // given sql query. If the query fails or does not return a single // column, `false` is returned in the second result. func (c *sqlConn) getServerValue(what, sql string) (driver.Value, bool) { - var dbVals [1]driver.Value - rows, err := c.Query(sql, nil) if err != nil { fmt.Fprintf(stderr, "warning: error retrieving the %s: %v\n", what, err) @@ -339,6 +354,8 @@ func (c *sqlConn) getServerValue(what, sql string) (driver.Value, bool) { return nil, false } + dbVals := make([]driver.Value, len(rows.Columns())) + err = rows.Next(dbVals[:]) if err != nil { fmt.Fprintf(stderr, "warning: invalid %s: %v\n", what, err) @@ -348,6 +365,61 @@ func (c *sqlConn) getServerValue(what, sql string) (driver.Value, bool) { return dbVals[0], true } +// parseLastQueryStatistics runs the "SHOW LAST QUERY STATISTICS" statements, +// performs sanity checks, and returns the exec latency and service latency from +// the sql row parsed as time.Duration. +func (c *sqlConn) getLastQueryStatistics() ( + execLatency time.Duration, + serviceLatency time.Duration, + err error, +) { + rows, err := c.Query("SHOW LAST QUERY STATISTICS", nil) + if err != nil { + return 0, 0, err + } + defer func() { _ = rows.Close() }() + + if len(rows.Columns()) != 4 { + return 0, 0, + errors.New("unexpected number of columns in SHOW LAST QUERY STATISTICS") + } + + if rows.Columns()[2] != "exec_latency" || rows.Columns()[3] != "service_latency" { + return 0, 0, + errors.New("unexpected columns in SHOW LAST QUERY STATISTICS") + } + + iter := newRowIter(rows, true /* showMoreChars */) + nRows := 0 + var execLatencyRaw string + var serviceLatencyRaw string + for { + row, err := iter.Next() + if err == io.EOF { + break + } else if err != nil { + return 0, 0, err + } + + execLatencyRaw = formatVal(row[2], false, false) + serviceLatencyRaw = formatVal(row[3], false, false) + + nRows++ + } + + if nRows != 1 { + return 0, 0, + errors.Newf("unexpected number of rows in SHOW LAST QUERY STATISTICS: %d", nRows) + } + + parsedExecLatency, _ := tree.ParseDInterval(execLatencyRaw) + parsedServiceLatency, _ := tree.ParseDInterval(serviceLatencyRaw) + + return time.Duration(parsedExecLatency.Duration.Nanos()), + time.Duration(parsedServiceLatency.Duration.Nanos()), + nil +} + // sqlTxnShim implements the crdb.Tx interface. // // It exists to support crdb.ExecuteInTxn. Normally, we'd hand crdb.ExecuteInTxn @@ -424,7 +496,7 @@ func (c *sqlConn) Query(query string, args []driver.Value) (*sqlRows, error) { } func (c *sqlConn) QueryRow(query string, args []driver.Value) ([]driver.Value, error) { - rows, err := makeQuery(query, args...)(c) + rows, _, err := makeQuery(query, args...)(c) if err != nil { return nil, err } @@ -634,10 +706,11 @@ func makeSQLClient(appName string, defaultMode defaultSQLDb) (*sqlConn, error) { return makeSQLConn(sqlURL), nil } -type queryFunc func(conn *sqlConn) (*sqlRows, error) +type queryFunc func(conn *sqlConn) (rows *sqlRows, isMultiStatementQuery bool, err error) func makeQuery(query string, parameters ...driver.Value) queryFunc { - return func(conn *sqlConn) (*sqlRows, error) { + return func(conn *sqlConn) (*sqlRows, bool, error) { + isMultiStatementQuery := len(parser.ScanStatements(query)) > 1 // driver.Value is an alias for interface{}, but must adhere to a restricted // set of types when being passed to driver.Queryer.Query (see // driver.IsValue). We use driver.DefaultParameterConverter to perform the @@ -648,17 +721,18 @@ func makeQuery(query string, parameters ...driver.Value) queryFunc { var err error parameters[i], err = driver.DefaultParameterConverter.ConvertValue(parameters[i]) if err != nil { - return nil, err + return nil, isMultiStatementQuery, err } } - return conn.Query(query, parameters) + rows, err := conn.Query(query, parameters) + return rows, isMultiStatementQuery, err } } // runQuery takes a 'query' with optional 'parameters'. // It runs the sql query and returns a list of columns names and a list of rows. func runQuery(conn *sqlConn, fn queryFunc, showMoreChars bool) ([]string, [][]string, error) { - rows, err := fn(conn) + rows, _, err := fn(conn) if err != nil { return nil, nil, err } @@ -698,7 +772,7 @@ var tagsWithRowsAffected = map[string]struct{}{ // It runs the sql query and writes output to 'w'. func runQueryAndFormatResults(conn *sqlConn, w io.Writer, fn queryFunc) error { startTime := timeutil.Now() - rows, err := fn(conn) + rows, isMultiStatementQuery, err := fn(conn) if err != nil { return handleCopyError(conn, err) } @@ -788,14 +862,23 @@ func runQueryAndFormatResults(conn *sqlConn, w io.Writer, fn queryFunc) error { return err } - if sqlCtx.showTimes { - // Present the time since the last result, or since the - // beginning of execution. Currently the execution engine makes - // all the work upfront so most of the time is accounted for by - // the 1st result; this is subject to change once CockroachDB - // evolves to stream results as statements are executed. - fmt.Fprintf(w, "\nTime: %s\n", queryCompleteTime.Sub(startTime)) - // Make users better understand any discrepancy they observe. + // We only show times for the first result set. + if sqlCtx.showTimes && !isMultiStatementQuery { + clientSideQueryTime := queryCompleteTime.Sub(startTime) + if sqlCtx.enableServerExecutionTimings { + execLatency, serviceLatency, err := conn.getLastQueryStatistics() + if err != nil { + return err + } + networkLatency := clientSideQueryTime - serviceLatency + + fmt.Fprintf(w, "\nServer Execution Time: %s\n", execLatency) + fmt.Fprintf(w, "Network Latency: %s\n", networkLatency) + } else { + // If the server doesn't support `SHOW LAST QUERY STATISTICS` statement, + // we revert to the pre-20.2 time formatting in the CLI. + fmt.Fprintf(w, "\nTime: %s\n", clientSideQueryTime) + } renderDelay := timeutil.Now().Sub(queryCompleteTime) if renderDelay >= 1*time.Second { fmt.Fprintf(w, @@ -804,8 +887,8 @@ func runQueryAndFormatResults(conn *sqlConn, w io.Writer, fn queryFunc) error { renderDelay) } fmt.Fprintln(w) - // Reset the clock. We ignore the rendering time. - startTime = timeutil.Now() + } else { + fmt.Fprintf(w, "Note: timings for multiple statements on a single line are not supported\n") } if more, err := rows.NextResultSet(); err != nil { diff --git a/pkg/sql/parser/parse.go b/pkg/sql/parser/parse.go index 491f3fa3b91b..c979d388f1ef 100644 --- a/pkg/sql/parser/parse.go +++ b/pkg/sql/parser/parse.go @@ -236,6 +236,24 @@ func ParseOne(sql string) (Statement, error) { return p.parseOneWithDepth(1, sql) } +// ScanStatements takes a sql string and returns potential sql statements +// by performing semi-colon delimited splitting. This function does not perform +// any parsing, as it is intended to be called from the client, and we never +// want to do client side parsing (with potentially old grammars). +func ScanStatements(sql string) (stmts []string) { + var p Parser + p.scanner.init(sql) + defer p.scanner.cleanup() + for { + sql, _, done := p.scanOneStmt() + if done { + break + } + stmts = append(stmts, sql) + } + return stmts +} + // ParseQualifiedTableName parses a SQL string of the form // `[ database_name . ] [ schema_name . ] table_name`. func ParseQualifiedTableName(sql string) (*tree.TableName, error) {