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

@@ -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.

pkg/cli/interactive_tests/test_timing.tcl

@@ -0,0 +1,30 @@
+#! /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 "Note: timings for multiple statements on a single line are not supported"
+end_test
+
+start_test "Test show_server_execution_times works correctly"
+send "\\set show_server_times=false\r"
+send "SELECT * FROM vehicles LIMIT 1;\r"
+eexpect "\nTime:"
+send "\\set show_server_times=true\r"
+send "SELECT * FROM vehicles LIMIT 1;\r"
+eexpect "Server Execution Time:"
+eexpect "Network Latency:"
+end_test

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_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 = " ?"
@@ -1304,7 +1315,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 +1346,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 +1429,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 +1536,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

pkg/cli/sql_util.go

@@ -29,8 +29,10 @@ 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/errorutil/unimplemented"
 	"github.com/cockroachdb/cockroach/pkg/util/log"
 	"github.com/cockroachdb/cockroach/pkg/util/timeutil"
 	"github.com/cockroachdb/cockroach/pkg/util/version"
@@ -170,6 +172,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 +314,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 +343,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 +355,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 +366,64 @@ 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() {
+		closeErr := rows.Close()
+		err = errors.CombineErrors(err, closeErr)
+	}()
+
+	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 +500,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 +710,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 := parser.HasMultipleStatements(query)
 		// 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 +725,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
 	}
@@ -696,14 +774,15 @@ var tagsWithRowsAffected = map[string]struct{}{
 
 // runQueryAndFormatResults takes a 'query' with optional 'parameters'.
 // It runs the sql query and writes output to 'w'.
-func runQueryAndFormatResults(conn *sqlConn, w io.Writer, fn queryFunc) error {
+func runQueryAndFormatResults(conn *sqlConn, w io.Writer, fn queryFunc) (err error) {
 	startTime := timeutil.Now()
-	rows, err := fn(conn)
+	rows, isMultiStatementQuery, err := fn(conn)
 	if err != nil {
 		return handleCopyError(conn, err)
 	}
 	defer func() {
-		_ = rows.Close()
+		closeErr := rows.Close()
+		err = errors.CombineErrors(err, closeErr)
 	}()
 	for {
 		// lib/pq is not able to tell us before the first call to Next()
@@ -789,23 +868,36 @@ func runQueryAndFormatResults(conn *sqlConn, w io.Writer, fn queryFunc) error {
 		}
 
 		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.
+			clientSideQueryTime := queryCompleteTime.Sub(startTime)
+			// We don't print timings for multi-statement queries as we don't have an
+			// accurate way to measure them currently. See #48180.
+			if isMultiStatementQuery {
+				// No need to print if no one's watching.
+				if sqlCtx.isInteractive {
+					fmt.Fprintf(stderr, "Note: timings for multiple statements on a single line are not supported. See %s.\n", unimplemented.MakeURL(48180))
+				}
+			} else 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,
+			if renderDelay >= 1*time.Second && sqlCtx.isInteractive {
+				fmt.Fprintf(stderr,
 					"Note: an additional delay of %s was spent formatting the results.\n"+
 						"You can use \\set display_format to change the formatting.\n",
 					renderDelay)
 			}
 			fmt.Fprintln(w)
-			// Reset the clock. We ignore the rendering time.
-			startTime = timeutil.Now()
 		}
 
 		if more, err := rows.NextResultSet(); err != nil {