From ca0d5b29e437a785ca9617038734d0c4efeaa215 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, when a user executed multiple statements on a single line in the CLI, we would send the string as-is to the server. This would skew statement execution timings by attributing all of the server execution time to the first statement. This patch fixes this issue by parsing the supplied string on the client side and sending invididual statements one at a time. This is in line with Postgres behavior. Additionally, this patch also changes the way we calculate the time displayed by the CLI. Previously, we would show the time it took between a client sending a request and recieving a result. This would include the client-server latency as well. Now instead of showing the total time, we switch to showing just the server execution time. This is done by issuing the `SHOW LAST QUERY STATISTICS` query underneath the hood. Fixes #48180 Informs #49450 Release note (cli change): The way the CLI now shows the server execution timing instead of the total time it took to recieve results. This means factors such as rendering time and client server latency are no longer accounted for in the timings that the CLI prints for a query execution. Additionally, if multiple statements are supplied on a single line, the timings displayed now are a more accurate representation than before. Earlier the time displayed for the first statement included the processing time for all the statements supplied in that line. This is no longer the case as individual statement timings now represent only their execution times. This brings us in line with the postgres CLI. --- pkg/cli/sql.go | 45 +++++++++++++++++++++++++++++---------------- pkg/cli/sql_util.go | 32 +++++++++++++++++++------------- 2 files changed, 48 insertions(+), 29 deletions(-) diff --git a/pkg/cli/sql.go b/pkg/cli/sql.go index bb29655a8bc8..973bbda0c28f 100644 --- a/pkg/cli/sql.go +++ b/pkg/cli/sql.go @@ -154,7 +154,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. @@ -1135,7 +1136,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. @@ -1163,7 +1164,28 @@ 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 { + stmts, err := parser.Parse(c.concatLines) + if err != nil { + c.exitErr = err + return cliStop + } + for _, stmt := range stmts { + c.doRunStatement(stmt.SQL) + if c.exitErr != nil { + if c.errExit { + return cliStop + } + return nextState + } + } + return nextState +} + +// doRunStatement runs a single sql statement. +func (c *cliState) doRunStatement(stmt string) { // 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 = " ?" @@ -1175,15 +1197,12 @@ 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 + return } } // Now run the statement/query. - c.exitErr = runQueryAndFormatResults(c.conn, os.Stdout, makeQuery(c.concatLines)) + c.exitErr = runQueryAndFormatResults(c.conn, os.Stdout, makeQuery(stmt)) if c.exitErr != nil { cliOutputError(stderr, c.exitErr, true /*showSeverity*/, false /*verbose*/) } @@ -1225,12 +1244,6 @@ func (c *cliState) doRunStatement(nextState cliStateEnum) cliStateEnum { } } } - - if c.exitErr != nil && c.errExit { - return cliStop - } - - return nextState } func (c *cliState) doDecidePath() cliStateEnum { @@ -1299,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)) @@ -1413,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 { diff --git a/pkg/cli/sql_util.go b/pkg/cli/sql_util.go index 9ba7bd0b4aa4..95723ff68097 100644 --- a/pkg/cli/sql_util.go +++ b/pkg/cli/sql_util.go @@ -320,8 +320,14 @@ 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 + return c.getServerValueFromColumnIndex(what, sql, 0) +} +// getServerValueFromColumnIndex retrieves the driverValue at a particular +// column index from the result of the given sql query. If the query fails or +// does not return at least as many columns as colIdx - 1, `false` is returned +// in the second result. +func (c *sqlConn) getServerValueFromColumnIndex(what, sql string, colIdx int) (driver.Value, bool) { rows, err := c.Query(sql, nil) if err != nil { fmt.Fprintf(stderr, "warning: error retrieving the %s: %v\n", what, err) @@ -329,18 +335,20 @@ func (c *sqlConn) getServerValue(what, sql string) (driver.Value, bool) { } defer func() { _ = rows.Close() }() - if len(rows.Columns()) == 0 { + if len(rows.Columns()) <= colIdx { fmt.Fprintf(stderr, "warning: cannot get the %s\n", what) 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) return nil, false } - return dbVals[0], true + return dbVals[colIdx], true } // sqlTxnShim implements the crdb.Tx interface. @@ -692,7 +700,6 @@ 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 { - startTime := timeutil.Now() rows, err := fn(conn) if err != nil { return handleCopyError(conn, err) @@ -784,13 +791,14 @@ 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. + // TODO(arul): This 2 is kind of ugly and unfortunate. + execLatencyRaw, hasVal := conn.getServerValueFromColumnIndex( + "last query statistics", `SHOW LAST QUERY STATISTICS`, 2 /* exec_latency */) + if hasVal { + execLatency := formatVal(execLatencyRaw, false, false) + parsed, _ := tree.ParseDInterval(execLatency) + fmt.Fprintf(w, "\nServer Execution Time: %s\n", time.Duration(parsed.Duration.Nanos())) + } renderDelay := timeutil.Now().Sub(queryCompleteTime) if renderDelay >= 1*time.Second { fmt.Fprintf(w, @@ -799,8 +807,6 @@ 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() } if more, err := rows.NextResultSet(); err != nil {