cli: incorrect query latencies reported by CLI

[mgartner]

Describe the problem

The latencies displayed in the CLI do not appear to be accurate always.

Please describe the issue you observed, and any steps we can take to reproduce it:

To Reproduce

What did you do? Describe in your own words.

If possible, provide steps to reproduce the behavior:

1. Start a free Cockroach Cloud cluster at https://cockroachlabs.cloud
2. Connect the CLI to the cluster via cockroach sql ...
3. Run the query below. Time the query and compare to the latency reported by the CLI:

For this query, the CLI reports a latency of 2.095s, but it's actually ~10s:

SELECT
  t.oid, t.typname, t.typelem, t.typdelim, t.typinput, r.rngsubtype, t.typtype, t.typbasetype
FROM
  pg_type AS t LEFT JOIN pg_range AS r ON oid = rngtypid
WHERE
  t.typname
  IN (
      'int2',
      'int4',
      'int8',
      'oid',
      'float4',
      'float8',
      'text',
      'varchar',
      'char',
      'name',
      'bpchar',
      'bool',
      'bit',
      'varbit',
      'timestamptz',
      'date',
      'money',
      'bytea',
      'point',
      'hstore',
      'json',
      'jsonb',
      'cidr',
      'inet',
      'uuid',
      'xml',
      'tsvector',
      'macaddr',
      'citext',
      'ltree',
      'line',
      'lseg',
      'box',
      'path',
      'polygon',
      'circle',
      'interval',
      'time',
      'timestamp',
      'numeric'
    )
  OR t.typtype IN ('r', 'e', 'd')
  OR t.typinput = 'array_in(cstring,oid,integer)'::REGPROCEDURE
  OR t.typelem != 0;

When I add EXPLAIN, the CLI reports a 66ms latency, but it's actually ~6s.

Environment:

Cluster version:

defaultdb> select version();
                                                  version
-----------------------------------------------------------------------------------------------------------
  CockroachDB CCL v20.2.4-47-ge9525c264b (x86_64-unknown-linux-gnu, built 2021/01/25 07:12:36, go1.13.14)

CLI version:

Build Tag:        v20.2.4
Build Time:       2021/01/21 00:12:56
Distribution:     CCL
Platform:         darwin amd64 (x86_64-apple-darwin14)
Go Version:       go1.13.14
C Compiler:       4.2.1 Compatible Clang 3.8.0 (tags/RELEASE_380/final)
Build Commit ID:  eda2309728392593162e962a61182eab6ab003ff
Build Type:       release

[mgartner]

When I simplify the query as below, the problem doesn't persist (or the difference in reported latency and real latency is too small for me to notice).

SELECT * FROM pg_type AS t WHERE
  t.typtype IN ('r', 'e', 'd')
  OR t.typinput = 'array_in(cstring,oid,integer)'::REGPROCEDURE
  OR t.typelem != 0;

[mgartner]

@jordanlewis discovered that the problem is caused by (1) the default CLI prompt requires a few round-trips to display and (2) the number of newlines in the query seem to amplify the number of round-trips.

This is proven by either (A) overriding the default prompt or by (B) removing all new lines from the query.

A. Override the default prompt and re-run the query. The latency reported appears accurate.

\set prompt1=>

B. With the default prompt, run the query without any newlines:

SELECT t.oid, t.typname, t.typelem, t.typdelim, t.typinput, r.rngsubtype, t.typtype, t.typbasetype FROM pg_type AS t LEFT JOIN pg_range AS r ON oid = rngtypid WHERE t.typname IN ( 'int2', 'int4', 'int8', 'oid', 'float4', 'float8', 'text', 'varchar', 'char', 'name', 'bpchar', 'bool', 'bit', 'varbit', 'timestamptz', 'date', 'money', 'bytea', 'point', 'hstore', 'json', 'jsonb', 'cidr', 'inet', 'uuid', 'xml', 'tsvector', 'macaddr', 'citext', 'ltree', 'line', 'lseg', 'box', 'path', 'polygon', 'circle', 'interval', 'time', 'timestamp', 'numeric') OR t.typtype IN ('r', 'e', 'd') OR t.typinput = 'array_in(cstring,oid,integer)'::REGPROCEDURE OR t.typelem != 0;