From 79304346369362c29682c55fbb7fcc66f0520dc7 Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Thu, 24 Sep 2020 12:13:23 +0200 Subject: [PATCH 1/4] cli: pass the input stream as argument to runInteractive() This makes it easier to process a file other than the standard input. Release note: None --- pkg/cli/auth.go | 2 +- pkg/cli/cli.go | 4 ---- pkg/cli/decode.go | 4 ++-- pkg/cli/demo.go | 3 ++- pkg/cli/sql.go | 20 ++++++++++---------- pkg/cli/sql_test.go | 6 +----- 6 files changed, 16 insertions(+), 23 deletions(-) diff --git a/pkg/cli/auth.go b/pkg/cli/auth.go index 252885e84c83..e75acd7dea37 100644 --- a/pkg/cli/auth.go +++ b/pkg/cli/auth.go @@ -64,7 +64,7 @@ func runLogin(cmd *cobra.Command, args []string) error { return err } - checkInteractive() + checkInteractive(os.Stdin) if cliCtx.isInteractive { fmt.Fprintf(stderr, `# # Example uses: diff --git a/pkg/cli/cli.go b/pkg/cli/cli.go index ea0074aa7505..a3ed7582aae1 100644 --- a/pkg/cli/cli.go +++ b/pkg/cli/cli.go @@ -127,10 +127,6 @@ func (e *cliError) FormatError(p errors.Printer) error { // to be captured. var stderr = log.OrigStderr -// stdin aliases os.Stdin; we use an alias here so that tests in this -// package can redirect the input of the CLI shell. -var stdin = os.Stdin - var versionCmd = &cobra.Command{ Use: "version", Short: "output version information", diff --git a/pkg/cli/decode.go b/pkg/cli/decode.go index 8236e16f38be..3d5d124d7be8 100644 --- a/pkg/cli/decode.go +++ b/pkg/cli/decode.go @@ -26,13 +26,13 @@ import ( ) func runDebugDecodeProto(_ *cobra.Command, _ []string) error { - if isatty.IsTerminal(stdin.Fd()) { + if isatty.IsTerminal(os.Stdin.Fd()) { fmt.Fprintln(stderr, `# Reading proto-encoded pieces of data from stdin. # Press Ctrl+C or Ctrl+D to terminate.`, ) } - return streamMap(os.Stdout, stdin, + return streamMap(os.Stdout, os.Stdin, func(s string) (bool, string, error) { return tryDecodeValue(s, debugDecodeProtoName) }) } diff --git a/pkg/cli/demo.go b/pkg/cli/demo.go index 108ff0d6c17a..a11c295c3735 100644 --- a/pkg/cli/demo.go +++ b/pkg/cli/demo.go @@ -14,6 +14,7 @@ import ( "context" gosql "database/sql" "fmt" + "os" "strings" "time" @@ -282,7 +283,7 @@ func runDemo(cmd *cobra.Command, gen workload.Generator) (err error) { } demoCtx.transientCluster = &c - checkInteractive() + checkInteractive(os.Stdin) if cliCtx.isInteractive { fmt.Printf(`# diff --git a/pkg/cli/sql.go b/pkg/cli/sql.go index 91c2fb119339..f0aa7625c742 100644 --- a/pkg/cli/sql.go +++ b/pkg/cli/sql.go @@ -1271,7 +1271,7 @@ func (c *cliState) doDecidePath() cliStateEnum { // runInteractive runs the SQL client interactively, presenting // a prompt to the user for each statement. -func runInteractive(conn *sqlConn) (exitErr error) { +func runInteractive(conn *sqlConn, cmdIn *os.File) (exitErr error) { c := cliState{conn: conn} state := cliStart @@ -1281,7 +1281,7 @@ func runInteractive(conn *sqlConn) (exitErr error) { } switch state { case cliStart: - cleanupFn, err := c.configurePreShellDefaults() + cleanupFn, err := c.configurePreShellDefaults(cmdIn) defer cleanupFn() if err != nil { return err @@ -1340,7 +1340,7 @@ func runInteractive(conn *sqlConn) (exitErr error) { // // The returned cleanupFn must be called even when the err return is // not nil. -func (c *cliState) configurePreShellDefaults() (cleanupFn func(), err error) { +func (c *cliState) configurePreShellDefaults(cmdIn *os.File) (cleanupFn func(), err error) { if cliCtx.terminalOutput { // If results are shown on a terminal also enable printing of // times by default. @@ -1373,11 +1373,11 @@ func (c *cliState) configurePreShellDefaults() (cleanupFn func(), err error) { // the doStart() method because of the defer. c.ins, c.exitErr = readline.InitFiles("cockroach", true, /* wideChars */ - stdin, os.Stdout, stderr) + cmdIn, os.Stdout, stderr) if errors.Is(c.exitErr, readline.ErrWidecharNotSupported) { log.Warning(context.TODO(), "wide character support disabled") c.ins, c.exitErr = readline.InitFiles("cockroach", - false, stdin, os.Stdout, stderr) + false, cmdIn, os.Stdout, stderr) } if c.exitErr != nil { return cleanupFn, c.exitErr @@ -1391,7 +1391,7 @@ func (c *cliState) configurePreShellDefaults() (cleanupFn func(), err error) { cleanupFn = func() { c.ins.Close() } } else { c.ins = noLineEditor - c.buf = bufio.NewReader(stdin) + c.buf = bufio.NewReader(cmdIn) cleanupFn = func() {} } @@ -1476,18 +1476,18 @@ func (c *cliState) runStatements(stmts []string) error { // checkInteractive sets the isInteractive parameter depending on the // execution environment and the presence of -e flags. -func checkInteractive() { +func checkInteractive(stdin *os.File) { // We don't consider sessions interactives unless we have a // serious hunch they are. For now, only `cockroach sql` *without* // `-e` has the ability to input from a (presumably) human user, // and we'll also assume that there is no human if the standard // input is not terminal-like -- likely redirected from a file, // etc. - cliCtx.isInteractive = len(sqlCtx.execStmts) == 0 && isatty.IsTerminal(os.Stdin.Fd()) + cliCtx.isInteractive = len(sqlCtx.execStmts) == 0 && isatty.IsTerminal(stdin.Fd()) } func runTerm(cmd *cobra.Command, args []string) error { - checkInteractive() + checkInteractive(os.Stdin) if cliCtx.isInteractive { // The user only gets to see the welcome message on interactive sessions. @@ -1513,7 +1513,7 @@ func runClient(cmd *cobra.Command, conn *sqlConn) error { // Enable safe updates, unless disabled. setupSafeUpdates(cmd, conn) - return runInteractive(conn) + return runInteractive(conn, os.Stdin) } // setupSafeUpdates attempts to enable "safe mode" if the session is diff --git a/pkg/cli/sql_test.go b/pkg/cli/sql_test.go index b0591094119d..d1674fd4b21a 100644 --- a/pkg/cli/sql_test.go +++ b/pkg/cli/sql_test.go @@ -71,7 +71,6 @@ select ''' f.Close() } _ = os.Remove(fname) - stdin = os.Stdin }() for _, test := range tests { @@ -90,10 +89,7 @@ select ''' fmt.Fprintln(stderr, err) return } - // Override the standard input for runInteractive(). - stdin = f - - err := runInteractive(conn) + err := runInteractive(conn, f) if err != nil { fmt.Fprintln(stderr, err) } From 7a0f3d61f0e8534d284a0e35c3f2e618c00d30cd Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Thu, 24 Sep 2020 12:57:01 +0200 Subject: [PATCH 2/4] cli: support `-f` to read SQL from a file Release note (cli change): `cockroach sql` and `cockroach demo` now support the command-line parameter `--input-file` (shorthand `-f`) to read commands from a named file. The behavior is the same as if the file was redirected on the standard input; in particular, the processing stops at the first error encountered (which is different from interactive usage with a prompt). Note that it is not (yet) possible to combine `-f` with `-e`. --- pkg/cli/cli_test.go | 29 +++++++++++++++++++++++++++++ pkg/cli/cliflags/flags.go | 15 ++++++++++++++- pkg/cli/context.go | 7 +++++++ pkg/cli/demo.go | 11 ++++++++--- pkg/cli/flags.go | 1 + pkg/cli/sql.go | 31 +++++++++++++++++++++++++++---- pkg/cli/testdata/inputfile.sql | 18 ++++++++++++++++++ 7 files changed, 104 insertions(+), 8 deletions(-) create mode 100644 pkg/cli/testdata/inputfile.sql diff --git a/pkg/cli/cli_test.go b/pkg/cli/cli_test.go index c672b17c0340..f6f878e71c73 100644 --- a/pkg/cli/cli_test.go +++ b/pkg/cli/cli_test.go @@ -2060,3 +2060,32 @@ func Example_dump_no_visible_columns() { // CREATE TABLE public.t (FAMILY "primary" (rowid) // ); } + +// Example_read_from_file tests the -f parameter. +// The input file contains a mix of client-side and +// server-side commands to ensure that both are supported with -f. +func Example_read_from_file() { + c := newCLITest(cliTestParams{}) + defer c.cleanup() + + c.RunWithArgs([]string{"sql", "-e", "select 1", "-f", "testdata/inputfile.sql"}) + c.RunWithArgs([]string{"sql", "-f", "testdata/inputfile.sql"}) + + // Output: + // sql -e select 1 -f testdata/inputfile.sql + // ERROR: unsupported combination: --execute and --file + // sql -f testdata/inputfile.sql + // SET + // CREATE TABLE + // > INSERT INTO test(s) VALUES ('hello'), ('world'); + // INSERT 2 + // > SELECT * FROM test; + // s + // hello + // world + // > SELECT undefined; + // ERROR: column "undefined" does not exist + // SQLSTATE: 42703 + // ERROR: column "undefined" does not exist + // SQLSTATE: 42703 +} diff --git a/pkg/cli/cliflags/flags.go b/pkg/cli/cliflags/flags.go index 41d31cd75b5a..a759fc99b299 100644 --- a/pkg/cli/cliflags/flags.go +++ b/pkg/cli/cliflags/flags.go @@ -256,7 +256,20 @@ Execute the SQL statement(s) on the command line, then exit. This flag may be specified multiple times and each value may contain multiple semicolon separated statements. If an error occurs in any statement, the command exits with a non-zero status code and further statements are not executed. The -results of each SQL statement are printed on the standard output.`, +results of each SQL statement are printed on the standard output. + +This flag is incompatible with --file / -f.`, + } + + File = FlagInfo{ + Name: "file", + Shorthand: "f", + Description: ` +Read and execute the SQL statement(s) from the specified file. +The file is processed as if it has been redirected on the standard +input of the shell. + +This flag is incompatible with --execute / -e.`, } Watch = FlagInfo{ diff --git a/pkg/cli/context.go b/pkg/cli/context.go index 1a73a142a41f..554dea0fd0c3 100644 --- a/pkg/cli/context.go +++ b/pkg/cli/context.go @@ -204,8 +204,14 @@ var sqlCtx = struct { setStmts statementsValue // execStmts is a list of statements to execute. + // Only valid if inputFile is empty. execStmts statementsValue + // inputFile is the file to read from. + // If empty, os.Stdin is used. + // Only valid if execStmts is empty. + inputFile string + // repeatDelay indicates that the execStmts should be "watched" // at the specified time interval. Zero disables // the watch. @@ -240,6 +246,7 @@ var sqlCtx = struct { func setSQLContextDefaults() { sqlCtx.setStmts = nil sqlCtx.execStmts = nil + sqlCtx.inputFile = "" sqlCtx.repeatDelay = 0 sqlCtx.safeUpdates = false sqlCtx.showTimes = false diff --git a/pkg/cli/demo.go b/pkg/cli/demo.go index a11c295c3735..8ab9ffe2704f 100644 --- a/pkg/cli/demo.go +++ b/pkg/cli/demo.go @@ -14,7 +14,6 @@ import ( "context" gosql "database/sql" "fmt" - "os" "strings" "time" @@ -253,6 +252,12 @@ func checkDemoConfiguration( } func runDemo(cmd *cobra.Command, gen workload.Generator) (err error) { + cmdIn, closeFn, err := getInputFile() + if err != nil { + return err + } + defer closeFn() + if gen, err = checkDemoConfiguration(cmd, gen); err != nil { return err } @@ -283,7 +288,7 @@ func runDemo(cmd *cobra.Command, gen workload.Generator) (err error) { } demoCtx.transientCluster = &c - checkInteractive(os.Stdin) + checkInteractive(cmdIn) if cliCtx.isInteractive { fmt.Printf(`# @@ -359,7 +364,7 @@ func runDemo(cmd *cobra.Command, gen workload.Generator) (err error) { conn := makeSQLConn(c.connURL) defer conn.Close() - return runClient(cmd, conn) + return runClient(cmd, conn, cmdIn) } func waitForLicense(licenseDone <-chan error) error { diff --git a/pkg/cli/flags.go b/pkg/cli/flags.go index 17e816866291..47bb2666089f 100644 --- a/pkg/cli/flags.go +++ b/pkg/cli/flags.go @@ -656,6 +656,7 @@ func init() { f := cmd.Flags() varFlag(f, &sqlCtx.setStmts, cliflags.Set) varFlag(f, &sqlCtx.execStmts, cliflags.Execute) + stringFlag(f, &sqlCtx.inputFile, cliflags.File) durationFlag(f, &sqlCtx.repeatDelay, cliflags.Watch) boolFlag(f, &sqlCtx.safeUpdates, cliflags.SafeUpdates) boolFlag(f, &sqlCtx.debugMode, cliflags.CliDebugMode) diff --git a/pkg/cli/sql.go b/pkg/cli/sql.go index f0aa7625c742..3840ab7b5aea 100644 --- a/pkg/cli/sql.go +++ b/pkg/cli/sql.go @@ -1486,8 +1486,31 @@ func checkInteractive(stdin *os.File) { cliCtx.isInteractive = len(sqlCtx.execStmts) == 0 && isatty.IsTerminal(stdin.Fd()) } +// getInputFile establishes where we are reading from. +func getInputFile() (cmdIn *os.File, closeFn func(), err error) { + if sqlCtx.inputFile == "" { + return os.Stdin, func() {}, nil + } + + if len(sqlCtx.execStmts) != 0 { + return nil, nil, errors.Newf("unsupported combination: --%s and --%s", cliflags.Execute.Name, cliflags.File.Name) + } + + f, err := os.Open(sqlCtx.inputFile) + if err != nil { + return nil, nil, err + } + return f, func() { _ = f.Close() }, nil +} + func runTerm(cmd *cobra.Command, args []string) error { - checkInteractive(os.Stdin) + cmdIn, closeFn, err := getInputFile() + if err != nil { + return err + } + defer closeFn() + + checkInteractive(cmdIn) if cliCtx.isInteractive { // The user only gets to see the welcome message on interactive sessions. @@ -1500,10 +1523,10 @@ func runTerm(cmd *cobra.Command, args []string) error { } defer conn.Close() - return runClient(cmd, conn) + return runClient(cmd, conn, cmdIn) } -func runClient(cmd *cobra.Command, conn *sqlConn) error { +func runClient(cmd *cobra.Command, conn *sqlConn, cmdIn *os.File) error { // Open the connection to make sure everything is OK before running any // statements. Performs authentication. if err := conn.ensureConn(); err != nil { @@ -1513,7 +1536,7 @@ func runClient(cmd *cobra.Command, conn *sqlConn) error { // Enable safe updates, unless disabled. setupSafeUpdates(cmd, conn) - return runInteractive(conn, os.Stdin) + return runInteractive(conn, cmdIn) } // setupSafeUpdates attempts to enable "safe mode" if the session is diff --git a/pkg/cli/testdata/inputfile.sql b/pkg/cli/testdata/inputfile.sql new file mode 100644 index 000000000000..c1d5c46fadcd --- /dev/null +++ b/pkg/cli/testdata/inputfile.sql @@ -0,0 +1,18 @@ +--- input file for Example_read_from_file. + +--- don't report timestamps: it makes the output non-deterministic. +\unset show_times + +USE defaultdb; +CREATE TABLE test(s STRING); + +-- make the reminder echo its SQL. +\set echo +INSERT INTO test(s) VALUES ('hello'), ('world'); +SELECT * FROM test; + +-- produce an error, to test that processing stops. +SELECT undefined; + +-- this is not executed +SELECT 'unseen'; From b5747d9a1acca184941fe03eeb44dd8fafcc695c Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Thu, 24 Sep 2020 16:45:42 +0200 Subject: [PATCH 3/4] cli/sql: further polish statement statistics The following rules are applied: - the breakdown is only displayed if the total execution time exceeds 1ms. We assume that (human) users don't care about the breakdown if a statement is faster than that. - if `verbose_timings` is unset (default), the server-side latencies are all grouped together (the "service latency") under a single `execution` label. - the user can invoke `\set verbose_timings` to get the full breakdown. Example outputs follow. The breakdown is omitted because the total time is under 1ms: ``` root@127.0.0.1:44820/defaultdb> select 1; ?column? ------------ 1 (1 row) Time: 0.000s total ``` A query is simple to parse/plan, but takes a while to execute because it produces a lot of data: ``` root@127.0.0.1:44820/defaultdb> select generate_series(1,10000); ... (10000 rows) Time: 0.013s total (execution 0.004s / network 0.009s) ``` A more complex statement: ``` root@127.0.0.1:44820/defaultdb> create table t(x int); CREATE TABLE Time: 0.003s total (execution 0.002s / network 0.001s) ``` Release note (cli change): The display of statement timings in the SQL shell (`cockroach sql` and `cockroach demo`) has been further simplified. --- pkg/cli/interactive_tests/test_timing.tcl | 14 ++--- pkg/cli/sql_util.go | 62 +++++++++++++++-------- 2 files changed, 48 insertions(+), 28 deletions(-) diff --git a/pkg/cli/interactive_tests/test_timing.tcl b/pkg/cli/interactive_tests/test_timing.tcl index fd9d8dd302b1..87b631d2745a 100644 --- a/pkg/cli/interactive_tests/test_timing.tcl +++ b/pkg/cli/interactive_tests/test_timing.tcl @@ -8,10 +8,10 @@ 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" +send "SELECT pg_sleep(0.02) FROM vehicles LIMIT 1;\r" eexpect "1 row" -eexpect "/ net" -eexpect "/ other" +eexpect "execution" +eexpect "network" # Ditto with multiple statements on one line send "SELECT * FROM vehicles LIMIT 1; CREATE TABLE t(a int);\r" @@ -21,10 +21,10 @@ 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" +send "SELECT pg_sleep(0.02) FROM vehicles LIMIT 1;\r" eexpect "\nTime:" send "\\set show_server_times=true\r" -send "SELECT * FROM vehicles LIMIT 1;\r" -eexpect "/ net" -eexpect "/ other" +send "SELECT pg_sleep(0.02) FROM vehicles LIMIT 1;\r" +eexpect "execution" +eexpect "network" end_test diff --git a/pkg/cli/sql_util.go b/pkg/cli/sql_util.go index 013bae185d0e..d3dda0391dde 100644 --- a/pkg/cli/sql_util.go +++ b/pkg/cli/sql_util.go @@ -199,7 +199,7 @@ func (c *sqlConn) ensureConn() error { // 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() + _, _, _, _, err := c.getLastQueryStatistics() if err != nil { fmt.Fprintf(stderr, "warning: cannot show server execution timings: unexpected column found\n") sqlCtx.enableServerExecutionTimings = false @@ -393,13 +393,12 @@ func (c *sqlConn) getServerValue(what, sql string) (driver.Value, bool) { // 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, + parseLat, planLat, execLat, serviceLat time.Duration, err error, ) { rows, err := c.Query("SHOW LAST QUERY STATISTICS", nil) if err != nil { - return 0, 0, err + return 0, 0, 0, 0, err } defer func() { closeErr := rows.Close() @@ -407,17 +406,22 @@ func (c *sqlConn) getLastQueryStatistics() ( }() if len(rows.Columns()) != 4 { - return 0, 0, + return 0, 0, 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, + if rows.Columns()[0] != "parse_latency" || + rows.Columns()[1] != "plan_latency" || + rows.Columns()[2] != "exec_latency" || + rows.Columns()[3] != "service_latency" { + return 0, 0, 0, 0, errors.New("unexpected columns in SHOW LAST QUERY STATISTICS") } iter := newRowIter(rows, true /* showMoreChars */) nRows := 0 + var parseLatencyRaw string + var planLatencyRaw string var execLatencyRaw string var serviceLatencyRaw string for { @@ -425,9 +429,11 @@ func (c *sqlConn) getLastQueryStatistics() ( if err == io.EOF { break } else if err != nil { - return 0, 0, err + return 0, 0, 0, 0, err } + parseLatencyRaw = formatVal(row[0], false, false) + planLatencyRaw = formatVal(row[1], false, false) execLatencyRaw = formatVal(row[2], false, false) serviceLatencyRaw = formatVal(row[3], false, false) @@ -435,14 +441,18 @@ func (c *sqlConn) getLastQueryStatistics() ( } if nRows != 1 { - return 0, 0, + return 0, 0, 0, 0, errors.Newf("unexpected number of rows in SHOW LAST QUERY STATISTICS: %d", nRows) } parsedExecLatency, _ := tree.ParseDInterval(execLatencyRaw) parsedServiceLatency, _ := tree.ParseDInterval(serviceLatencyRaw) + parsedPlanLatency, _ := tree.ParseDInterval(planLatencyRaw) + parsedParseLatency, _ := tree.ParseDInterval(parseLatencyRaw) - return time.Duration(parsedExecLatency.Duration.Nanos()), + return time.Duration(parsedParseLatency.Duration.Nanos()), + time.Duration(parsedPlanLatency.Duration.Nanos()), + time.Duration(parsedExecLatency.Duration.Nanos()), time.Duration(parsedServiceLatency.Duration.Nanos()), nil } @@ -989,23 +999,33 @@ func maybeShowTimes( } // If discrete server/network timings are available, also print them. - execLatency, serviceLatency, err := conn.getLastQueryStatistics() + parseLat, planLat, execLat, serviceLat, err := conn.getLastQueryStatistics() if err != nil { fmt.Fprintf(stderr, "\nwarning: %v", err) return } - networkLatency := clientSideQueryTime - serviceLatency + fmt.Fprint(stderr, " total") + + networkLat := clientSideQueryTime - serviceLat + otherLat := serviceLat - parseLat - planLat - execLat if sqlCtx.verboseTimings { - fmt.Fprintf(w, " total (exec %s / net %s / other %s)\n", - execLatency, networkLatency, serviceLatency-execLatency) - } else { - // Simplified display: just show percentages. - totalSeconds := clientSideQueryTime.Seconds() - fmt.Fprintf(w, " total (exec %.1f%% / net %.1f%% / other %.1f%%)\n", - execLatency.Seconds()*100/totalSeconds, - networkLatency.Seconds()*100/totalSeconds, - (serviceLatency-execLatency).Seconds()*100/totalSeconds) + fmt.Fprintf(w, " (parse %s / plan %s / exec %s / other %s / network %s)\n", + parseLat, planLat, execLat, otherLat, networkLat) + } else if clientSideQueryTime.Milliseconds() > 1 { + // Simplified display: just show the execution/network breakdown. + // + // Note: we omit the report of percentages for queries that + // last for a millisecond or less. This is because for such + // small queries, the detail is just noise to the human observer. + sep := " (" + reportTiming := func(label string, lat time.Duration) { + fmt.Fprintf(w, "%s%s %.3fs", sep, label, lat.Seconds()) + sep = " / " + } + reportTiming("execution", serviceLat) + reportTiming("network", networkLat) + fmt.Fprintln(w, ")") } } From b5bd89c3f999dfa13d57ea287736828fcadb5d8e Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Thu, 24 Sep 2020 19:16:57 +0200 Subject: [PATCH 4/4] cli/sql: display timings in milliseconds for sub-second results Compare: ``` root@127.0.0.1:30822/defaultdb> select pg_sleep(0.1); pg_sleep ------------ true (1 row) Time: 104ms total (execution 104ms / network 0ms) root@127.0.0.1:30822/defaultdb> select pg_sleep(1); pg_sleep ------------ true (1 row) Time: 1.003s total (execution 1.003s / network 0.000s) ``` (Rule: if the total time is under a second, all the timings are printed as integer milliseconds.) Release note: None --- pkg/cli/sql_util.go | 19 +++++++++++++++---- 1 file changed, 15 insertions(+), 4 deletions(-) diff --git a/pkg/cli/sql_util.go b/pkg/cli/sql_util.go index d3dda0391dde..d78f8989e575 100644 --- a/pkg/cli/sql_util.go +++ b/pkg/cli/sql_util.go @@ -985,12 +985,23 @@ func maybeShowTimes( // output will be execution time(s). fmt.Fprintln(w) + // Suggested by Radu: for sub-second results, show simplified + // timings in milliseconds. + unit := "s" + multiplier := 1. + precision := 3 + if clientSideQueryTime.Seconds() < 1 { + unit = "ms" + multiplier = 1000. + precision = 0 + } + if sqlCtx.verboseTimings { fmt.Fprintf(w, "Time: %s", clientSideQueryTime) } else { // Simplified displays: human users typically can't // distinguish sub-millisecond latencies. - fmt.Fprintf(w, "Time: %.3fs", clientSideQueryTime.Seconds()) + fmt.Fprintf(w, "Time: %.*f%s", precision, clientSideQueryTime.Seconds()*multiplier, unit) } if !sqlCtx.enableServerExecutionTimings { @@ -1012,15 +1023,15 @@ func maybeShowTimes( if sqlCtx.verboseTimings { fmt.Fprintf(w, " (parse %s / plan %s / exec %s / other %s / network %s)\n", parseLat, planLat, execLat, otherLat, networkLat) - } else if clientSideQueryTime.Milliseconds() > 1 { + } else { // Simplified display: just show the execution/network breakdown. // - // Note: we omit the report of percentages for queries that + // Note: we omit the report details for queries that // last for a millisecond or less. This is because for such // small queries, the detail is just noise to the human observer. sep := " (" reportTiming := func(label string, lat time.Duration) { - fmt.Fprintf(w, "%s%s %.3fs", sep, label, lat.Seconds()) + fmt.Fprintf(w, "%s%s %.*f%s", sep, label, precision, lat.Seconds()*multiplier, unit) sep = " / " } reportTiming("execution", serviceLat)