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 cockroachdb#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 cockroachdb#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_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
 

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"

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@

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

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
 

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