executor: improve trace format='row' #9029

tiancaiamao · 2019-01-11T14:32:13Z

What problem does this PR solve?

In #8357, the trace result is in json format, used by web UI.

This commit add a row format for it, which look like this:

mysql> trace format='row' select * from t1 order by c limit 3;
+---------------------------+---------------------------+------------+
| operation                 | startTS                   | duration   |
+---------------------------+---------------------------+------------+
| session.getTxnFuture      | Jan 11 21:33:09.933212243 | 4.181µs    |
|   ├─session.Execute       | Jan 11 21:33:09.933207819 | 763.708µs  |
|   ├─session.ParseSQL      | Jan 11 21:33:09.933293211 | 57.002µs   |
|   ├─executor.Compile      | Jan 11 21:33:09.933388076 | 233.427µs  |
|   ├─session.runStmt       | Jan 11 21:33:09.933658842 | 198.985µs  |
|   ├─session.CommitTxn     | Jan 11 21:33:09.933808415 | 11.947µs   |
|   ├─recordSet.Next        | Jan 11 21:33:09.934038447 | 691.335µs  |
|   ├─topN.Next             | Jan 11 21:33:09.934042362 | 663.15µs   |
|   ├─tableReader.Next      | Jan 11 21:33:09.934050669 | 548.271µs  |
|   ├─tableReader.Next      | Jan 11 21:33:09.934671187 | 5µs        |
|   ├─recordSet.Next        | Jan 11 21:33:09.934756161 | 22.416µs   |
|   └─topN.Next             | Jan 11 21:33:09.934760051 | 1.553µs    |
+---------------------------+---------------------------+------------+
12 rows in set (0.00 sec)

What is changed and how it works?

Write the trace result to chunk in row format.

There are some small pitfalls I'll investigate later:

The opentracing span parent-children relationship seems incorrect
Add more columns to provide useful info

We support trace format='json' ... and trace format='row' ...
Maybe I should also make format=row the default one.

Check List

Tests

Unit test
Manual test (add detailed scripts or steps below)

Related changes

Need to update the documentation

tiancaiamao · 2019-01-11T14:32:59Z

PTAL @jackysp @lysu

mysql> trace format='row' select * from trace where id = 0; +---------------------------+-----------------+------------+ | operation | startTS | duration | +---------------------------+-----------------+------------+ | session.getTxnFuture | 22:08:38.247834 | 78.909µs | | ├─session.Execute | 22:08:38.247829 | 1.478487ms | | ├─session.ParseSQL | 22:08:38.248457 | 71.159µs | | ├─executor.Compile | 22:08:38.248578 | 45.329µs | | ├─session.runStmt | 22:08:38.248661 | 75.13µs | | ├─session.CommitTxn | 22:08:38.248699 | 13.213µs | | └─recordSet.Next | 22:08:38.249340 | 155.317µs | +---------------------------+-----------------+------------+ 7 rows in set (0.01 sec)

codecov-io · 2019-01-11T14:47:26Z

Codecov Report

Merging #9029 into master will increase coverage by 0.05%.
The diff coverage is 77.04%.

@@            Coverage Diff             @@
##           master    #9029      +/-   ##
==========================================
+ Coverage   67.58%   67.63%   +0.05%     
==========================================
  Files         364      364              
  Lines       75477    75471       -6     
==========================================
+ Hits        51011    51047      +36     
+ Misses      19973    19927      -46     
- Partials     4493     4497       +4

Impacted Files	Coverage Δ
executor/trace.go	`74.15% <77.04%> (+45.73%)`	⬆️
ddl/session_pool.go	`82.75% <0%> (-10.35%)`	⬇️
ddl/delete_range.go	`77.14% <0%> (-1.72%)`	⬇️
store/tikv/lock_resolver.go	`41.7% <0%> (-0.95%)`	⬇️
expression/schema.go	`94.95% <0%> (+0.84%)`	⬆️
executor/join.go	`78.96% <0%> (+1.03%)`	⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 504b10c...59e0d0f. Read the comment docs.

jackysp · 2019-01-12T03:04:50Z

/run-all-tests

jackysp

LGTM
PTAL @lysu

jackysp · 2019-01-12T03:06:52Z

executor/trace.go

+	}
+
+	chk.AppendString(0, prefix+suffix+t.Span.Name())
+	chk.AppendString(1, start.Format("15:04:05.000000"))


It is OK for me, but "15:04:05.000000" is still a little strange.

This control the time format output.
Go use pattern match to control the output format, https://godoc.org/time#Parse
And the layout string always use this date: 2006 01 02 15 04 05, it's a special number

if you want the result looks like "hh:mm:ss.xxxxxx" , the layout should be "15:04:05.000000"

tiancaiamao · 2019-01-12T17:23:19Z

/run-all-tests

lysu · 2019-01-13T03:49:16Z

/run-all-tests tidb-test=pr/715

lysu · 2019-01-13T04:03:53Z

/run-all-tests

lysu · 2019-01-13T04:08:58Z

LGTM to current code, but maybe more refine the span name in the next @tiancaiamao

mysql> trace format="row" select * from t join t2 on t2.id = t.id where t.id = 2;
+---------------------------+-----------------+------------+
| operation                 | startTS         | duration   |
+---------------------------+-----------------+------------+
| session.getTxnFuture      | 12:02:26.316169 | 3.014µs    |
|   ├─session.Execute       | 12:02:26.316166 | 867.827µs  |
|   ├─session.ParseSQL      | 12:02:26.316213 | 54.937µs   |
|   ├─executor.Compile      | 12:02:26.316297 | 379.766µs  |
|   ├─session.runStmt       | 12:02:26.316714 | 272.396µs  |
|   ├─session.CommitTxn     | 12:02:26.316955 | 9.873µs    |
|   ├─recordSet.Next        | 12:02:26.317053 | 449.804µs  |
|   ├─tableReader.Next      | 12:02:26.317115 | 324.444µs  |
|   └─tableReader.Next      | 12:02:26.317125 | 288.022µs  |
+---------------------------+-----------------+------------+
9 rows in set (0.01 sec)

from this two table with same name we don't know which table have question, also miss join execution info, and maybe trace insert is useful too.

lysu · 2019-01-13T04:12:04Z

/run-all-tests tidb-test=pr/715

lysu · 2019-01-13T04:17:00Z

/run-common-test tidb-test=pr/715
/run-integration-common-test tidb-test=pr/715

zhouqiang-cl · 2019-01-13T08:14:36Z

/run-common-test

lysu · 2019-01-13T08:30:44Z

/run-common-test tidb-test=pr/716
/run-integration-common-test tidb-test=pr/716

tiancaiamao force-pushed the trace-row branch from c2896eb to 59e0d0f Compare January 11, 2019 14:35

jackysp reviewed Jan 12, 2019

View reviewed changes

Merge branch 'master' into trace-row

d8e00a0

Merge branch 'master' into trace-row

ac95d4c

lysu approved these changes Jan 13, 2019

View reviewed changes

jackysp added type/enhancement The issue or PR belongs to an enhancement. status/LGT2 Indicates that a PR has LGTM 2. labels Jan 13, 2019

zz-jason merged commit 8ac79f3 into pingcap:master Jan 13, 2019

zz-jason added the status/all tests passed label Jan 13, 2019

tiancaiamao deleted the trace-row branch March 24, 2020 06:58

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

executor: improve trace format='row' #9029

executor: improve trace format='row' #9029

tiancaiamao commented Jan 11, 2019

tiancaiamao commented Jan 11, 2019

codecov-io commented Jan 11, 2019

jackysp commented Jan 12, 2019

jackysp left a comment

jackysp Jan 12, 2019

tiancaiamao Jan 12, 2019

tiancaiamao commented Jan 12, 2019

lysu commented Jan 13, 2019

lysu commented Jan 13, 2019

lysu commented Jan 13, 2019

lysu commented Jan 13, 2019

lysu commented Jan 13, 2019

zhouqiang-cl commented Jan 13, 2019

lysu commented Jan 13, 2019

executor: improve trace format='row' #9029

executor: improve trace format='row' #9029

Conversation

tiancaiamao commented Jan 11, 2019

What problem does this PR solve?

What is changed and how it works?

Check List

tiancaiamao commented Jan 11, 2019

codecov-io commented Jan 11, 2019

Codecov Report

jackysp commented Jan 12, 2019

jackysp left a comment

Choose a reason for hiding this comment

jackysp Jan 12, 2019

Choose a reason for hiding this comment

tiancaiamao Jan 12, 2019

Choose a reason for hiding this comment

tiancaiamao commented Jan 12, 2019

lysu commented Jan 13, 2019

lysu commented Jan 13, 2019

lysu commented Jan 13, 2019

lysu commented Jan 13, 2019

lysu commented Jan 13, 2019

zhouqiang-cl commented Jan 13, 2019

lysu commented Jan 13, 2019