Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

cli: provide auto_trace as replacement to SHOW TRACE FOR <stmt> #27805

Merged
merged 1 commit into from
Jul 20, 2018

Conversation

knz
Copy link
Contributor

@knz knz commented Jul 20, 2018

The SHOW TRACE FOR syntax form was removed from CockroachDB SQL
because it was hard to implement correctly server-side.

However this does not mean that the need for it did not exist. Folk
were moderately unhappy to lose a feature that was exploited
productively during performance analysis and general troubleshooting.

To respond to the need, this patch instead provides a feature in
cockroach sql that replaces the previous SHOW TRACE FOR
syntax. For example:

> \set auto_trace on
> SELECT 1
+----------+
| ?column? |
+----------+
|        1 |
+----------+
(1 row)

Time: 327.38µs

+----------------------------------+------------+------------------------------------------------------------------+---------------------------------------+----------+-------------------+------+
|            timestamp             |    age     |                             message                              |                  tag                  | location |     operation     | span |
+----------------------------------+------------+------------------------------------------------------------------+---------------------------------------+----------+-------------------+------+
| 2018-07-20 15:25:29.09039+00:00  | 0s         | === SPAN START: session recording ===                            |                                       |          | session recording |    0 |
| 2018-07-20 15:25:29.09041+00:00  | 19µs997ns  | [NoTxn pos:22] executing Sync                                    | [n1,client=127.0.0.1:16847,user=root] |          | session recording |    0 |
| 2018-07-20 15:25:29.09048+00:00  | 89µs917ns  | [NoTxn pos:23] executing ExecStmt: SELECT 1                      | [n1,client=127.0.0.1:16847,user=root] |          | session recording |    0 |
[...]
+----------------------------------+------------+------------------------------------------------------------------+---------------------------------------+----------+-------------------+------+
(22 rows)

Time: 1.836533ms

That is, for every statement executed, the shell also produces the
trace for that statement in a separate result below.

A trace is also produced in case the statement produces a SQL error.

It works as follows:

  • a new client-side option auto_trace is provided (configurable with
    \set).
  • when set to non-off, it causes every subsequent statement to be
    enclosed in:
    • SET tracing = off; SET tracing = on, <options...> at the
      beginning where <options...> is the content of the variable
      auto_trace.
    • SET tracing = off; SHOW <option> TRACE FOR SESSION at the end,
      where <option> is either empty or kv if auto_trace contains
      kv.

Release note (cli change): A new client-side option auto_trace is
provided to facilitate usage of session tracing.

The SHOW TRACE FOR <stmt> syntax form was removed from CockroachDB SQL
because it was hard to implement correctly server-side.

However this does not mean that the need for it did not exist. Folk
were moderately unhappy to lose a feature that was exploited
productively during performance analysis and general troubleshooting.

To respond to the need, this patch instead provides a feature in
`cockroach sql` that replaces the previous SHOW TRACE FOR <stmt>
syntax. For example:

```
> \set auto_trace on
> SELECT 1
+----------+
| ?column? |
+----------+
|        1 |
+----------+
(1 row)

Time: 327.38µs

+----------------------------------+------------+------------------------------------------------------------------+---------------------------------------+----------+-------------------+------+
|            timestamp             |    age     |                             message                              |                  tag                  | location |     operation     | span |
+----------------------------------+------------+------------------------------------------------------------------+---------------------------------------+----------+-------------------+------+
| 2018-07-20 15:25:29.09039+00:00  | 0s         | === SPAN START: session recording ===                            |                                       |          | session recording |    0 |
| 2018-07-20 15:25:29.09041+00:00  | 19µs997ns  | [NoTxn pos:22] executing Sync                                    | [n1,client=127.0.0.1:16847,user=root] |          | session recording |    0 |
| 2018-07-20 15:25:29.09048+00:00  | 89µs917ns  | [NoTxn pos:23] executing ExecStmt: SELECT 1                      | [n1,client=127.0.0.1:16847,user=root] |          | session recording |    0 |
[...]
+----------------------------------+------------+------------------------------------------------------------------+---------------------------------------+----------+-------------------+------+
(22 rows)

Time: 1.836533ms
```

That is, for every statement executed, the shell also produces the
trace for that statement in a separate result below.

A trace is also produced in case the statement produces a SQL error.

It works as follows:

- a new client-side option `auto_trace` is provided (configurable with
  `\set`).
- when set to non-off, it causes every subsequent statement to be
  enclosed in:
  - `SET tracing = off; SET tracing = on, <options...>` at the
	 beginning where `<options...>` is the content of the variable
	 `auto_trace`.
  - `SET tracing = off; SHOW <option> TRACE FOR SESSION` at the end,
	where `<option>` is either empty or `kv` if `auto_trace` contains
	`kv`.

Release note (cli change): A new client-side option `auto_trace` is
provided to facilitate usage of session tracing.
@knz knz added this to Triage in (DEPRECATED) SQL Front-end, Lang & Semantics via automation Jul 20, 2018
@knz knz added this to To do in DB Server & Security via automation Jul 20, 2018
@knz knz requested a review from a team as a code owner July 20, 2018 15:30
@knz knz requested a review from a team July 20, 2018 15:30
@cockroach-teamcity
Copy link
Member

This change is Reviewable

@knz
Copy link
Contributor Author

knz commented Jul 20, 2018

cc @tschottdorf you may have an opinion on the usability

@knz knz added the docs-todo label Jul 20, 2018
@knz knz moved this from Triage to Current milestone in (DEPRECATED) SQL Front-end, Lang & Semantics Jul 20, 2018
@jordanlewis
Copy link
Member

LGTM. This makes me wonder whether we should also add a non-"auto" version of this, e.g. \trace ANY SQL GOES HERE

@knz
Copy link
Contributor Author

knz commented Jul 20, 2018

@jordanlewis that was my first idea but the architecture of our CLI does not allow this without a major rewrite. So no (not yet).

@knz
Copy link
Contributor Author

knz commented Jul 20, 2018

TFYR

bors r+

craig bot pushed a commit that referenced this pull request Jul 20, 2018
27802: distsqlrun: plumb kv tracing into distsql r=jordanlewis a=jordanlewis

Previously, kv tracing only worked in local SQL. Now, FlowSetupRequest
and FlowCtx are augmented with traceKV flags, so DistSQL can get in on
the fun as well.

Release note (sql change): kv traces (SHOW KV TRACE FOR SESSION) now
work for distsql-executed queries as well.

27805: cli: provide `auto_trace` as replacement to SHOW TRACE FOR <stmt> r=knz a=knz

The SHOW TRACE FOR <stmt> syntax form was removed from CockroachDB SQL
because it was hard to implement correctly server-side.

However this does not mean that the need for it did not exist. Folk
were moderately unhappy to lose a feature that was exploited
productively during performance analysis and general troubleshooting.

To respond to the need, this patch instead provides a feature in
`cockroach sql` that replaces the previous SHOW TRACE FOR <stmt>
syntax. For example:

```
> \set auto_trace on
> SELECT 1
+----------+
| ?column? |
+----------+
|        1 |
+----------+
(1 row)

Time: 327.38µs

+----------------------------------+------------+------------------------------------------------------------------+---------------------------------------+----------+-------------------+------+
|            timestamp             |    age     |                             message                              |                  tag                  | location |     operation     | span |
+----------------------------------+------------+------------------------------------------------------------------+---------------------------------------+----------+-------------------+------+
| 2018-07-20 15:25:29.09039+00:00  | 0s         | === SPAN START: session recording ===                            |                                       |          | session recording |    0 |
| 2018-07-20 15:25:29.09041+00:00  | 19µs997ns  | [NoTxn pos:22] executing Sync                                    | [n1,client=127.0.0.1:16847,user=root] |          | session recording |    0 |
| 2018-07-20 15:25:29.09048+00:00  | 89µs917ns  | [NoTxn pos:23] executing ExecStmt: SELECT 1                      | [n1,client=127.0.0.1:16847,user=root] |          | session recording |    0 |
[...]
+----------------------------------+------------+------------------------------------------------------------------+---------------------------------------+----------+-------------------+------+
(22 rows)

Time: 1.836533ms
```

That is, for every statement executed, the shell also produces the
trace for that statement in a separate result below.

A trace is also produced in case the statement produces a SQL error.

It works as follows:

- a new client-side option `auto_trace` is provided (configurable with
  `\set`).
- when set to non-off, it causes every subsequent statement to be
  enclosed in:
  - `SET tracing = off; SET tracing = on, <options...>` at the
	 beginning where `<options...>` is the content of the variable
	 `auto_trace`.
  - `SET tracing = off; SHOW <option> TRACE FOR SESSION` at the end,
	where `<option>` is either empty or `kv` if `auto_trace` contains
	`kv`.

Release note (cli change): A new client-side option `auto_trace` is
provided to facilitate usage of session tracing.

Co-authored-by: Jordan Lewis <jordanthelewis@gmail.com>
Co-authored-by: Raphael 'kena' Poss <knz@cockroachlabs.com>
@craig
Copy link
Contributor

craig bot commented Jul 20, 2018

Build succeeded

@craig craig bot merged commit 287e4cc into cockroachdb:master Jul 20, 2018
DB Server & Security automation moved this from To do to Done Jul 20, 2018
@knz knz moved this from Current milestone to Finished (milestone 0703) in (DEPRECATED) SQL Front-end, Lang & Semantics Jul 20, 2018
@tbg
Copy link
Member

tbg commented Jul 20, 2018 via email

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants