*: trace the execution of the insert operation #11667

tiancaiamao · 2019-08-07T11:56:19Z

What problem does this PR solve?

This simple insert operation takes 30ms! I'm trying to figure out why it's so damn slow.

insert into t values (21, 66, 6, 27, 23) on duplicate key update id = id + 1,a = a+1 , b = b+1, c = c+1, d = d+1;

mysql> show create table t;
+-------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table | Create Table                                                                                                                                                                                                                                                                                                                                                                           |
+-------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| t     | CREATE TABLE `t` (
  `id` int(11) NOT NULL,
  `a` int(11) DEFAULT NULL,
  `b` int(11) DEFAULT NULL,
  `c` int(11) DEFAULT NULL,
  `d` int(11) DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `i_a` (`a`),
  KEY `i_b` (`b`),
  KEY `i_c` (`c`),
  KEY `i_d` (`d`),
  UNIQUE KEY `i_ac` (`a`,`c`),
  UNIQUE KEY `i_bd` (`b`,`d`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin |
+-------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql> select * from t;
+----+------+------+------+------+
| id | a    | b    | c    | d    |
+----+------+------+------+------+
| 11 |    7 |    8 |    9 |   10 |
| 12 |    6 |    7 |    8 |    9 |
| 21 |   16 |   17 |   18 |   19 |
+----+------+------+------+------+
3 rows in set (0.01 sec)

What is changed and how it works?

Add code to trace the execution of the insert operation.
I'd like to trace all operations that visit the network.

And here is why:

mysql> trace format = 'row' insert into t values (21, 66, 6, 27, 23) on duplicate key update id = id + 1,a = a+1 , b = b+1, c = c+1, d = d+1;
+-------------------------------------------------+-----------------+-------------+
| operation                                       | startTS         | duration    |
+-------------------------------------------------+-----------------+-------------+
| session.Execute                                 | 19:41:40.208872 | 30.3379ms   |
|   ├─session.ParseSQL                            | 19:41:40.208968 | 178.753µs   |
|   ├─executor.Compile                            | 19:41:40.209208 | 310.554µs   |
|   ├─session.runStmt                             | 19:41:40.209576 | 29.580799ms |
|   │ ├─executor.handleNoDelayExecutor            | 19:41:40.209624 | 5.633641ms  |
|   │ │ └─*executor.InsertExec.Next               | 19:41:40.209640 | 5.586157ms  |
|   │ │   ├─tikvTxn.BatchGet                      | 19:41:40.209789 | 1.142624ms  |
|   │ │   ├─batchCheck.initDupOldRowValue         | 19:41:40.210996 | 43.709µs    |
|   │ │   │ └─tikvTxn.BatchGet                    | 19:41:40.211011 | 3.167µs     |
|   │ │   └─InsertExec.updateDupRow               | 19:41:40.211071 | 4.126649ms  |
|   │ │     └─executor.updateRecord               | 19:41:40.211143 | 3.929455ms  |
|   │ │       ├─index.Create                      | 19:41:40.212195 | 933.116µs   |
|   │ │       └─index.Create                      | 19:41:40.213309 | 1.622564ms  |
|   │ └─session.CommitTxn                         | 19:41:40.215382 | 23.746444ms |
|   │   └─tikvTxn.Commit                          | 19:41:40.215403 | 23.690628ms |
|   │     ├─twoPhaseCommitter.prewriteKeys        | 19:41:40.215501 | 10.378328ms |
|   │     ├─tikvStore.getTimestampWithRetry       | 19:41:40.226032 | 1.411919ms  |
|   │     └─twoPhaseCommitter.commitKeys          | 19:41:40.227547 | 11.485828ms |
|   └─session.getTxnFuture                        | 19:41:40.208879 | 13.02µs     |
+-------------------------------------------------+-----------------+-------------+
19 rows in set (0.03 sec)

From the result, I can see that we still did not do a good job on the unique indices.

BatchGet twice in the batchChecker;
visit tikv in index.Create to check the unique conditions;
and I'm still investigating why prewrite & commit take so long...

WIP

Check List

Tests

No code

Code changes

Has exported function/method change

Side effects

Increased code complexity

Related changes

Need to cherry-pick to the release branch

It's better to cherry-pick this PR because without it we'll meet more conflicts.

codecov · 2019-08-08T08:22:28Z

Codecov Report

Merging #11667 into master will not change coverage.
The diff coverage is n/a.

@@             Coverage Diff             @@
##             master     #11667   +/-   ##
===========================================
  Coverage   81.6406%   81.6406%           
===========================================
  Files           428        428           
  Lines         93707      93707           
===========================================
  Hits          76503      76503           
  Misses        11788      11788           
  Partials       5416       5416

tiancaiamao · 2019-08-08T08:26:22Z

I try to make the trace reaches to rpcClient.SendRequest
Now it looks like this:

mysql> trace format = 'row' insert into t values (43, 23, 12, 77, 32) on duplicate key update id = id + 1,a = a+1 , b = b+1, c = c+1, d = d+1;
+-------------------------------------------------+-----------------+-------------+
| operation                                       | startTS         | duration    |
+-------------------------------------------------+-----------------+-------------+
| session.Execute                                 | 16:24:19.572421 | 39.994665ms |
|   ├─session.ParseSQL                            | 16:24:19.572534 | 162.915µs   |
|   ├─executor.Compile                            | 16:24:19.572756 | 267.989µs   |
|   ├─session.runStmt                             | 16:24:19.573076 | 39.304889ms |
|   │ ├─executor.handleNoDelayExecutor            | 16:24:19.573119 | 6.052298ms  |
|   │ │ └─*executor.InsertExec.Next               | 16:24:19.573135 | 6.015389ms  |
|   │ │   ├─tikvTxn.BatchGet                      | 16:24:19.573350 | 1.543199ms  |
|   │ │   │ └─rpcClient.SendRequest               | 16:24:19.573403 | 1.423014ms  |
|   │ │   ├─batchCheck.initDupOldRowValue         | 16:24:19.574930 | 1.090234ms  |
|   │ │   │ └─tikvTxn.BatchGet                    | 16:24:19.574959 | 1.029877ms  |
|   │ │   │   └─rpcClient.SendRequest             | 16:24:19.574990 | 925.623µs   |
|   │ │   └─InsertExec.updateDupRow               | 16:24:19.576058 | 3.027731ms  |
|   │ │     └─executor.updateRecord               | 16:24:19.576247 | 2.749795ms  |
|   │ │       ├─rpcClient.SendRequest             | 16:24:19.576370 | 687.618µs   |
|   │ │       ├─index.Create                      | 16:24:19.577181 | 851.474µs   |
|   │ │       │ └─rpcClient.SendRequest           | 16:24:19.577207 | 735.859µs   |
|   │ │       └─index.Create                      | 16:24:19.578069 | 844.256µs   |
|   │ │         └─rpcClient.SendRequest           | 16:24:19.578108 | 721.879µs   |
|   │ └─session.CommitTxn                         | 16:24:19.579276 | 33.0969ms   |
|   │   └─tikvTxn.Commit                          | 16:24:19.579297 | 33.062775ms |
|   │     ├─twoPhaseCommitter.prewriteKeys        | 16:24:19.579425 | 29.441927ms |
|   │     │ └─rpcClient.SendRequest               | 16:24:19.579498 | 29.34235ms  |
|   │     ├─tikvStore.getTimestampWithRetry       | 16:24:19.608877 | 180.765µs   |
|   │     └─twoPhaseCommitter.commitKeys          | 16:24:19.609081 | 3.262209ms  |
|   │       └─rpcClient.SendRequest               | 16:24:19.609119 | 3.198497ms  |
|   └─session.getTxnFuture                        | 16:24:19.572427 | 23.292µs    |
+-------------------------------------------------+-----------------+-------------+
26 rows in set (0.04 sec)

ngaut · 2019-08-08T08:32:18Z

Could you remove startTS column?

tiancaiamao · 2019-08-08T09:46:20Z

/rebuild

@ngaut Although the tree reveals the call stack, the duration of the parent span duration may not always greater than it's children.
If we take concurrency into consideration, the startTS can give us more information.

For example:

mysql> trace format = 'row' select * from t;
+--------------------------------------------+-----------------+------------+
| operation                                  | startTS         | duration   |
+--------------------------------------------+-----------------+------------+
| session.Execute                            | 17:01:21.201420 | 1.575289ms |
|   ├─session.ParseSQL                       | 17:01:21.201505 | 58.211µs   |
|   ├─executor.Compile                       | 17:01:21.201604 | 513.539µs  |
|   ├─session.runStmt                        | 17:01:21.202175 | 747.428µs  |
|   │ ├─tableReader.Open                     | 17:01:21.202670 | 156.727µs  |
|   │ │ └─distsql.Select                     | 17:01:21.202712 | 62.119µs   |
|   │ │   └─rpcClient.SendRequest            | 17:01:21.202964 | 1.063196ms |
|   │ └─session.CommitTxn                    | 17:01:21.202878 | 14.917µs   |
|   ├─session.getTxnFuture                   | 17:01:21.201427 | 13.092µs   |
|   ├─*executor.TableReaderExecutor.Next     | 17:01:21.203028 | 1.314519ms |
|   └─*executor.TableReaderExecutor.Next     | 17:01:21.204439 | 8.407µs    |
+--------------------------------------------+-----------------+------------+
11 rows in set (0.00 sec)

distsql.Select spawn a goroutine to run the fetch operation which calls rpcClient.SendRequest, so the duration of distsql.Select (62.119µs) is smaller than rpcClient.SendRequest (1.063196ms)

If we run some asynchronous code, this can be misleading:

| session.Execute                            | 4ms |
|   ├─session.runStmt                        | 1ms   |
|   │ └─session.getTxnFuture                 | 100ms |
|   ├─session.CommitTxn                      | 1ms   |
|   ├─*executor.TableReaderExecutor.Next     | 1ms   |
|   └─*executor.TableReaderExecutor.Next     | 1ms   |

Does the whole process take 4ms or 100ms? which one?
We can be more clear about the asynchronous process with the startTS column:

| session.Execute                            | 17:01:21.202000 | 4ms |
|   ├─session.runStmt                        | 17:01:21.202100 | 1ms   |
|   │ └─session.getTxnFuture                 | 17:01:21.202106 | 100ms |
|   ├─session.CommitTxn                      | 17:01:21.202200 | 1ms   |
|   ├─*executor.TableReaderExecutor.Next     | 17:01:21.202300 | 1ms   |
|   └─*executor.TableReaderExecutor.Next     | 17:01:21.202400 | 1ms   |

ngaut · 2019-08-08T12:43:51Z

Thanks

tiancaiamao · 2019-08-09T02:11:42Z

PTAL @jackysp @lysu

jackysp

Please resolve the conflicts.

tiancaiamao · 2019-08-09T05:47:46Z

Conflict resolved @jackysp

lysu

LGTM

jackysp

LGTM

tiancaiamao · 2019-08-09T06:15:58Z

/run-all-tests

sre-bot · 2019-08-09T06:17:32Z

/run-all-tests

*: trace the execution of the insert operation

b665dec

tiancaiamao added the status/WIP label Aug 7, 2019

tiancaiamao added 2 commits August 8, 2019 15:01

trace tikvclient.SendRequest

b4179b5

fix CI

95c7733

tiancaiamao changed the title *: trace the execution of the insert operation [WIP] *: trace the execution of the insert operation Aug 8, 2019

tiancaiamao added type/enhancement and removed status/WIP labels Aug 8, 2019

make golint happy

c1a07d2

Merge branch 'master' into trace-insert

a7193bf

Merge branch 'master' into trace-insert

39895f8

jackysp reviewed Aug 9, 2019

View reviewed changes

lysu self-requested a review August 9, 2019 05:47

lysu reviewed Aug 9, 2019

View reviewed changes

lysu added the status/LGT1 Indicates that a PR has LGTM 1. label Aug 9, 2019

jackysp approved these changes Aug 9, 2019

View reviewed changes

jackysp added the status/can-merge Indicates a PR has been approved by a committer. label Aug 9, 2019

Merge branch 'master' into trace-insert

b0f5524

sre-bot merged commit d210889 into pingcap:master Aug 9, 2019

tiancaiamao deleted the trace-insert branch August 9, 2019 08:36

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

*: trace the execution of the insert operation #11667

*: trace the execution of the insert operation #11667

tiancaiamao commented Aug 7, 2019

codecov bot commented Aug 8, 2019 •

edited

tiancaiamao commented Aug 8, 2019

ngaut commented Aug 8, 2019

tiancaiamao commented Aug 8, 2019

ngaut commented Aug 8, 2019

tiancaiamao commented Aug 9, 2019

jackysp left a comment

tiancaiamao commented Aug 9, 2019

lysu left a comment

jackysp left a comment

tiancaiamao commented Aug 9, 2019 •

edited

sre-bot commented Aug 9, 2019

*: trace the execution of the insert operation #11667

*: trace the execution of the insert operation #11667

Conversation

tiancaiamao commented Aug 7, 2019

What problem does this PR solve?

What is changed and how it works?

Check List

codecov bot commented Aug 8, 2019 • edited

Codecov Report

tiancaiamao commented Aug 8, 2019

ngaut commented Aug 8, 2019

tiancaiamao commented Aug 8, 2019

ngaut commented Aug 8, 2019

tiancaiamao commented Aug 9, 2019

jackysp left a comment

Choose a reason for hiding this comment

tiancaiamao commented Aug 9, 2019

lysu left a comment

Choose a reason for hiding this comment

jackysp left a comment

Choose a reason for hiding this comment

tiancaiamao commented Aug 9, 2019 • edited

sre-bot commented Aug 9, 2019

codecov bot commented Aug 8, 2019 •

edited

tiancaiamao commented Aug 9, 2019 •

edited