store,kv: snapshot doesn't cache the non-exists kv entries lead to poor 'insert ignore' performance #12872

tiancaiamao · 2019-10-22T09:27:39Z

What problem does this PR solve?

The Snapshot should cache all the BatchGet() KV entries, including the non-exist ones.
This commit fixes a bug (start from #12108) that non-exist KV entries are not cached, causing insert ignore to access TiKV every time and the performance is poor.

What is changed and how it works?

The confusing API convention leads to this bug. Some places use len(value) = 0 in map[key]value to represent non-exist, some places use _, ok := map[key]value; !ok to represent non-exist ... and in the end, we forget to cache the non-exist information.

After this change, we can see that the tikvSnapshot.get doesn't call rpc SendRequest anymore.

See the tracing result to verify that:

mysql> trace format='row' insert ignore into t values (16, 16);
+---------------------------------------------------+-----------------+------------+
| operation                                         | startTS         | duration   |
+---------------------------------------------------+-----------------+------------+
| trace                                             | 16:54:17.747308 | 2.522179ms |
|   └─session.Execute                               | 16:54:17.747320 | 2.471526ms |
|     ├─session.ParseSQL                            | 16:54:17.747341 | 53.34µs    |
|     ├─executor.Compile                            | 16:54:17.747617 | 170.713µs  |
|     │ └─session.getTxnFuture                      | 16:54:17.747644 | 4.3µs      |
|     └─session.runStmt                             | 16:54:17.747827 | 1.886016ms |
|       ├─executor.handleNoDelayExecutor            | 16:54:17.747899 | 856.666µs  |
|       │ └─*executor.InsertExec.Next               | 16:54:17.747911 | 789.649µs  |
|       │   ├─prefetchUniqueIndices                 | 16:54:17.747985 | 583.39µs   |
|       │   │ └─tikvTxn.BatchGet                    | 16:54:17.747995 | 529.101µs  |
|       │   │   └─RPCClient.SendRequest             | 16:54:17.748104 | 362.006µs  |
|       │   └─tikvSnapshot.get                      | 16:54:17.748599 | 31.144µs   |
|       └─session.CommitTxn                         | 16:54:17.748805 | 882.35µs   |
|         └─session.doCommitWitRetry                | 16:54:17.748812 | 851.158µs  |
|           └─tikvTxn.Commit                        | 16:54:17.748822 | 770.733µs  |
|             ├─twoPhaseCommitter.prewriteKeys      | 16:54:17.748846 | 297.166µs  |
|             │ └─RPCClient.SendRequest             | 16:54:17.748897 | 209.762µs  |
|             ├─tikvStore.getTimestampWithRetry     | 16:54:17.749197 | 12.927µs   |
|             └─twoPhaseCommitter.commitKeys        | 16:54:17.749260 | 273.851µs  |
|               └─RPCClient.SendRequest             | 16:54:17.749301 | 172.921µs  |
+---------------------------------------------------+-----------------+------------+
20 rows in set (0.00 sec)

Check List

Tests

Manual test (add detailed scripts or steps below)

This is not a bug related to correctness.

Side effects

Possible performance boost (huge, in some cases)

Related changes

Need to cherry-pick to the release branch

Release note

Write release note for bug-fix or new feature.

…or 'insert ignore' performance Snapshot should cache all the BatchGet() kv entries, including the non-exist ones. This commit fix a bug that non-exist kv entries are not cached, causing `insert ignore` to access TiKV everytime and the performance is poor.

tiancaiamao · 2019-10-22T09:28:09Z

PTAL @jackysp @crazycs520

shenli · 2019-10-22T09:40:19Z

Could you add benchamrk result here?

jackysp

LGTM for the code

tiancaiamao · 2019-10-22T12:21:08Z

mysql> trace format='row' insert ignore into dst1 select * from sbtest1 limit 50;
+----------------------------------------------------------+-----------------+--------------+
| operation                                                | startTS         | duration     |
+----------------------------------------------------------+-----------------+--------------+
| trace                                                    | 20:11:36.385361 | 100.702686ms |
|   └─session.Execute                                      | 20:11:36.385374 | 100.677011ms |
|     ├─session.ParseSQL                                   | 20:11:36.385390 | 55.448µs     |
|     ├─executor.Compile                                   | 20:11:36.385505 | 404.423µs    |
|     │ └─session.getTxnFuture                             | 20:11:36.385520 | 7.793µs      |
|     └─session.runStmt                                    | 20:11:36.385933 | 100.060201ms |
|       ├─TableReaderExecutor.Open                         | 20:11:36.385981 | 77.319µs     |
|       │ └─distsql.Select                                 | 20:11:36.386001 | 38.835µs     |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.386162 | 6.123584ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.386191 | 6.282342ms   |
|       │   └─rpcClient.SendRequest                        | 20:11:36.386208 | 6.07743ms    |
|       ├─executor.handleNoDelayExecutor                   | 20:11:36.386077 | 89.493798ms  |
|       │ └─*executor.InsertExec.Next                      | 20:11:36.386085 | 89.350512ms  |
|       │   ├─*executor.LimitExec.Next                     | 20:11:36.386099 | 6.27469ms    |
|       │   │ └─*executor.TableReaderExecutor.Next         | 20:11:36.386103 | 6.255563ms   |
|       │   ├─*executor.LimitExec.Next                     | 20:11:36.392568 | 36.496µs     |
|       │   │ └─*executor.TableReaderExecutor.Next         | 20:11:36.392574 | 13.426µs     |
|       │   ├─*executor.LimitExec.Next                     | 20:11:36.392750 | 2.044µs      |
|       │   ├─prefetchUniqueIndices                        | 20:11:36.392889 | 1.860276ms   |
|       │   │ └─tikvTxn.BatchGet                           | 20:11:36.392905 | 1.828416ms   |
|       │   │   └─rpcClient.SendRequest                    | 20:11:36.392942 | 1.744313ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.394779 | 1.758971ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.396623 | 1.623987ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.398322 | 1.404693ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.399810 | 1.462372ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.401331 | 1.669213ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.403062 | 1.410324ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.404540 | 1.44024ms    |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.406029 | 2.049317ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.408263 | 1.642501ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.409968 | 1.897815ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.411973 | 1.347933ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.413393 | 1.315475ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.414773 | 1.2406ms     |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.416067 | 1.26719ms    |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.417382 | 1.448037ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.418940 | 1.528471ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.420530 | 1.633153ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.422253 | 2.054297ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.424487 | 1.358581ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.425937 | 1.343464ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.427347 | 1.335826ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.428741 | 1.420161ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.430218 | 1.371186ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.431658 | 1.379946ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.433081 | 1.374192ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.434509 | 1.351431ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.435920 | 1.415206ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.437405 | 1.822241ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.439317 | 3.100847ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.442665 | 1.383902ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.444125 | 1.317812ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.445510 | 1.528771ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.447108 | 1.434719ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.448623 | 1.444765ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.450149 | 1.475868ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.451703 | 1.440326ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.453199 | 1.333799ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.454591 | 1.359274ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.456027 | 1.354474ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.457453 | 1.446745ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.458953 | 1.3553ms     |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.460370 | 1.401218ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.461818 | 1.425161ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.463306 | 1.415466ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.464764 | 1.393022ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.466211 | 1.474054ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.467767 | 1.423053ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.469255 | 2.564316ms   |
|       │   ├─rpcClient.SendRequest                        | 20:11:36.471968 | 1.935937ms   |
|       │   └─rpcClient.SendRequest                        | 20:11:36.473964 | 1.430606ms   |
|       └─session.CommitTxn                                | 20:11:36.475615 | 10.37002ms   |
|         └─session.doCommitWitRetry                       | 20:11:36.475618 | 10.359507ms  |
|           └─tikvTxn.Commit                               | 20:11:36.475622 | 10.332044ms  |
|             ├─twoPhaseCommitter.prewriteKeys             | 20:11:36.475651 | 4.972172ms   |
|             │ └─rpcClient.SendRequest                    | 20:11:36.475678 | 4.907565ms   |
|             ├─tikvStore.getTimestampWithRetry            | 20:11:36.480640 | 230.728µs    |
|             └─twoPhaseCommitter.commitKeys               | 20:11:36.480892 | 5.040692ms   |
|               └─rpcClient.SendRequest                    | 20:11:36.480925 | 4.966844ms   |
+----------------------------------------------------------+-----------------+--------------+
79 rows in set (0.12 sec)

I'm making a comparison... if those rpcClient.SendRequest are still not intuitive enough

I create a table like this:

mysql> show create table sbtest1;
+---------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table   | Create Table                                                                                                                                                                                                                                                                                               |
+---------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| sbtest1 | CREATE TABLE `sbtest1` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `k` int(11) NOT NULL DEFAULT '0',
  `c` char(120) NOT NULL DEFAULT '',
  `pad` char(60) NOT NULL DEFAULT '',
  PRIMARY KEY (`id`),
  KEY `k_1` (`k`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin AUTO_INCREMENT=1069375 |
+---------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.01 sec)

and fill the table with 100w rows:

mysql> select count(*) from sbtest1;
+----------+
| count(*) |
+----------+
|  1000000 |
+----------+
1 row in set (0.47 sec)

and create another table, set tidb_batch_insert, then:

mysql> set @@tidb_batch_insert = true;                                                                                                                                                                Query OK, 0 rows affected (0.00 sec)

mysql> insert ignore into dst1 select * from sbtest1;
Query OK, 1000000 rows affected (53.04 sec)
Records: 1000000  Duplicates: 0  Warnings: 0

This result is under the TiDB binary of this commit.
The other one is still running ... I'll post the result after it finish ...

tiancaiamao · 2019-10-22T12:25:17Z

By the way, I mock a 1ms network latency (for both) because I'm testing on my laptop (no so obvious penalty for networking).

I guess at least 20mins have passed away.

mysql> select count(*) from dst2;
+----------+
| count(*) |
+----------+
|   720000 |
+----------+
1 row in set (0.32 sec)

tiancaiamao · 2019-10-22T12:32:21Z

The result is here, use master branch @shenli

mysql> insert ignore into dst2 select * from sbtest1;
Query OK, 1000000 rows affected (31 min 46.71 sec)
Records: 1000000  Duplicates: 0  Warnings: 0

codecov · 2019-10-22T12:55:35Z

Codecov Report

Merging #12872 into master will increase coverage by 0.3866%.
The diff coverage is n/a.

@@               Coverage Diff               @@
##             master    #12872        +/-   ##
===============================================
+ Coverage   80.0693%   80.456%   +0.3866%     
===============================================
  Files           465       465                
  Lines        107262    109333      +2071     
===============================================
+ Hits          85884     87965      +2081     
+ Misses        14934     14920        -14     
- Partials       6444      6448         +4

tiancaiamao · 2019-10-22T12:56:21Z

/run-all-tests

tiancaiamao · 2019-10-22T13:03:34Z

PTAL @crazycs520 @coocood

coocood · 2019-10-23T02:23:32Z

@tiancaiamao
We don't need to care if there is an entry in the map, we can simply do:

cached[key] = m[key]

jackysp

could we add a unit test case, e.g.trace fomat='row' insert ignore?

tiancaiamao · 2019-10-23T02:53:11Z

@tiancaiamao
We don't need to care if there is an entry in the map, we can simply do:
cached[key] = m[key]

That's exactly the bug!
When the key doesn't exist, there is no m[key] entry, and this information is not cached! @coocood

tiancaiamao · 2019-10-23T02:54:38Z

could we add a unit test case, e.g.trace fomat='row' insert ignore?

The result is difficult to check. @jackysp

coocood · 2019-10-23T02:59:57Z

@tiancaiamao
We don't need to care if there is an entry in the map, we can simply do:
cached[key] = m[key]
That's exactly the bug!
When the key doesn't exist, there is no m[key] entry, and this information is not cached! @coocood

It's cached, after this operation, _, ok := cached[key], ok is true.

coocood · 2019-10-23T03:37:04Z

LGTM

crazycs520

LGTM

jackysp · 2019-10-23T03:40:37Z

could we add a unit test case, e.g.trace fomat='row' insert ignore?

The result is difficult to check. @jackysp

We could check if it send the kv request in the result set.

crazycs520

LGTM

jackysp

Need a test case.

tiancaiamao · 2019-10-23T03:44:29Z

/run-all-tests

could we add a unit test case, e.g.trace fomat='row' insert ignore?

The result is difficult to check. @jackysp

We could check if it send the kv request in the result set.

There are always SendRequest in the result set, before or after this PR!
We have to check if there are SendRequest under snapshot.get
But the trace result may be changing, but check things like that is vulnerable. @jackysp

tiancaiamao · 2019-10-23T03:48:40Z

Need a test case.

Any idea about how to write that test?

tiancaiamao · 2019-10-23T06:59:26Z

PTAL @jackysp

jackysp · 2019-10-23T07:01:59Z

LGTM

sre-bot · 2019-10-23T07:04:30Z

/run-all-tests

sre-bot · 2019-10-23T07:11:27Z

cherry pick to release-3.0 failed

sre-bot · 2019-10-23T07:14:15Z

cherry pick to release-3.1 failed

…or 'insert ignore' performance (pingcap#12872)

…or 'insert ignore' performance (#12872) (#12898)

…ect/tidb into feature-add-udf-support * 'feature-add-udf-support' of https://github.com/JustProject/tidb: (26 commits) *: fix bug that the kill command doesn't work when the killed session is waiting for the pessimistic lock (pingcap#12852) executor: fix the projection upon the indexLookUp in indexLookUpJoin can't get result. (pingcap#12889) planner, executor: support create view on union (pingcap#12595) planner/cascades: introduce TransformationID in cascades planner (pingcap#12879) executor: fix data race in test (pingcap#12910) executor: reuse chunk row for insert on duplicate update (pingcap#12847) ddl: speed up tests (pingcap#12888) executor: speed up test (pingcap#12896) expression: implement vectorized evaluation for `builtinSecondSig` (pingcap#12886) expression: implement vectorized evaluation for `builtinJSONObjectSig` (pingcap#12663) expression: speed up builtinRepeatSig by using MergeNulls (pingcap#12674) expression: speed up unit tests under the expression package (pingcap#12887) store,kv: snapshot doesn't cache the non-exists kv entries lead to poor 'insert ignore' performance (pingcap#12872) executor: fix data race in `GetDirtyTable()` (pingcap#12767) domain: increase TTL to reduce the occurrence of reporting min startTS errors (pingcap#12578) executor: split test for speed up (pingcap#12881) executor: fix inconsistent of grants privileges with MySQL when executing `grant all on ...` (pingcap#12330) expression: implement vectorized evaluation for `builtinJSONUnquoteSig` (pingcap#12841) tune grpc connection count between tidb and tikv (pingcap#12884) Makefile: change test parallel to 8 (pingcap#12885) ...

…or 'insert ignore' performance pingcap#12872

…or 'insert ignore' performance (pingcap#12872)

tiancaiamao added type/enhancement The issue or PR belongs to an enhancement. component/tikv needs-cherry-pick-3.0 labels Oct 22, 2019

jackysp reviewed Oct 22, 2019

View reviewed changes

tiancaiamao added the status/all tests passed label Oct 22, 2019

jackysp reviewed Oct 23, 2019

View reviewed changes

tiancaiamao added 2 commits October 23, 2019 11:23

address comment

b593624

Merge branch 'master' into insert-ignore-non-exist

e5c36eb

tiancaiamao force-pushed the insert-ignore-non-exist branch from 3fcb401 to e5c36eb Compare October 23, 2019 03:28

crazycs520 reviewed Oct 23, 2019

View reviewed changes

jackysp requested changes Oct 23, 2019

View reviewed changes

address comment

e85de23

tiancaiamao force-pushed the insert-ignore-non-exist branch from 64ea7eb to e85de23 Compare October 23, 2019 06:59

jackysp approved these changes Oct 23, 2019

View reviewed changes

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

Merge branch 'master' into insert-ignore-non-exist

ab7829d

sre-bot merged commit 58fc7d4 into pingcap:master Oct 23, 2019

tiancaiamao deleted the insert-ignore-non-exist branch October 23, 2019 07:09

tiancaiamao added a commit to tiancaiamao/tidb that referenced this pull request Oct 23, 2019

store,kv: snapshot doesn't cache the non-exists kv entries lead to po…

fff05b9

…or 'insert ignore' performance (pingcap#12872)

tiancaiamao mentioned this pull request Oct 23, 2019

store,kv: snapshot doesn't cache the non-exists kv entries lead to poor 'insert ignore' performance (#12872) #12898

Merged

sre-bot pushed a commit that referenced this pull request Oct 23, 2019

store,kv: snapshot doesn't cache the non-exists kv entries lead to po…

c9000ab

…or 'insert ignore' performance (#12872) (#12898)

tiancaiamao mentioned this pull request Oct 24, 2019

sysbench: add a 'insert ignore' bench test with unique indices pingcap/tidb-bench#52

Merged

tiancaiamao added a commit to tiancaiamao/tidb that referenced this pull request Nov 11, 2019

store,kv: snapshot doesn't cache the non-exists kv entries lead to po…

1682ebb

…or 'insert ignore' performance pingcap#12872

tiancaiamao mentioned this pull request Nov 11, 2019

store,kv: snapshot doesn't cache the non-exists kv entries lead to poor 'insert ignore' performance #12872 #13362

Closed

XiaTianliang pushed a commit to XiaTianliang/tidb that referenced this pull request Dec 21, 2019

store,kv: snapshot doesn't cache the non-exists kv entries lead to po…

26de495

…or 'insert ignore' performance (pingcap#12872)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

store,kv: snapshot doesn't cache the non-exists kv entries lead to poor 'insert ignore' performance #12872

store,kv: snapshot doesn't cache the non-exists kv entries lead to poor 'insert ignore' performance #12872

tiancaiamao commented Oct 22, 2019

tiancaiamao commented Oct 22, 2019

shenli commented Oct 22, 2019

jackysp left a comment

tiancaiamao commented Oct 22, 2019

tiancaiamao commented Oct 22, 2019 •

edited

Loading

tiancaiamao commented Oct 22, 2019

codecov bot commented Oct 22, 2019 •

edited

Loading

tiancaiamao commented Oct 22, 2019

tiancaiamao commented Oct 22, 2019

coocood commented Oct 23, 2019

jackysp left a comment

tiancaiamao commented Oct 23, 2019

tiancaiamao commented Oct 23, 2019

coocood commented Oct 23, 2019

coocood commented Oct 23, 2019

crazycs520 left a comment

jackysp commented Oct 23, 2019

crazycs520 left a comment

jackysp left a comment

tiancaiamao commented Oct 23, 2019

tiancaiamao commented Oct 23, 2019

tiancaiamao commented Oct 23, 2019

jackysp commented Oct 23, 2019

sre-bot commented Oct 23, 2019

sre-bot commented Oct 23, 2019

sre-bot commented Oct 23, 2019

store,kv: snapshot doesn't cache the non-exists kv entries lead to poor 'insert ignore' performance #12872

store,kv: snapshot doesn't cache the non-exists kv entries lead to poor 'insert ignore' performance #12872

Conversation

tiancaiamao commented Oct 22, 2019

What problem does this PR solve?

What is changed and how it works?

Check List

tiancaiamao commented Oct 22, 2019

shenli commented Oct 22, 2019

jackysp left a comment

Choose a reason for hiding this comment

tiancaiamao commented Oct 22, 2019

tiancaiamao commented Oct 22, 2019 • edited Loading

tiancaiamao commented Oct 22, 2019

codecov bot commented Oct 22, 2019 • edited Loading

Codecov Report

tiancaiamao commented Oct 22, 2019

tiancaiamao commented Oct 22, 2019

coocood commented Oct 23, 2019

jackysp left a comment

Choose a reason for hiding this comment

tiancaiamao commented Oct 23, 2019

tiancaiamao commented Oct 23, 2019

coocood commented Oct 23, 2019

coocood commented Oct 23, 2019

crazycs520 left a comment

Choose a reason for hiding this comment

jackysp commented Oct 23, 2019

crazycs520 left a comment

Choose a reason for hiding this comment

jackysp left a comment

Choose a reason for hiding this comment

tiancaiamao commented Oct 23, 2019

tiancaiamao commented Oct 23, 2019

tiancaiamao commented Oct 23, 2019

jackysp commented Oct 23, 2019

sre-bot commented Oct 23, 2019

sre-bot commented Oct 23, 2019

sre-bot commented Oct 23, 2019

tiancaiamao commented Oct 22, 2019 •

edited

Loading

codecov bot commented Oct 22, 2019 •

edited

Loading