KVClient批写入tikv至region拆分后region异常

🪐 TiDB 技术问题
1

【 TiDB 使用环境】测试
【 TiDB 版本】
【复现路径】
KVClient批写入tikv，超过96w条后region拆分，此后tikv任何查询写入均报Region invalid: null

【遇到的问题：问题现象及影响】
tikv查询或插入出现如下错误
Exception in thread “main” org.tikv.common.exception.GrpcException: retry is exhausted.
at org.tikv.common.util.ConcreteBackOffer.logThrowError(ConcreteBackOffer.java:266)
at org.tikv.common.util.ConcreteBackOffer.doBackOffWithMaxSleep(ConcreteBackOffer.java:251)
at org.tikv.common.util.ConcreteBackOffer.doBackOff(ConcreteBackOffer.java:190)
at org.tikv.raw.RawKVClient.put(RawKVClient.java:164)
at org.tikv.raw.RawKVClient.put(RawKVClient.java:142)
at com.ebupt.test.tikv.TiKV.main(TiKV.java:71)
Caused by: org.tikv.common.exception.TiClientInternalException: Region invalid: null
at org.tikv.common.region.RegionManager.getRegionStorePairByKey(RegionManager.java:188)
at org.tikv.common.region.RegionStoreClient$RegionStoreClientBuilder.build(RegionStoreClient.java:1438)
at org.tikv.common.region.RegionStoreClient$RegionStoreClientBuilder.build(RegionStoreClient.java:1428)
at org.tikv.raw.RawKVClient.put(RawKVClient.java:158)

【资源配置】
三台16G / 8c 部署tikv和pd

【附件：截图/日志/监控】
批写入超过region分隔界限后tikv日志如下：
[2023/04/07 14:03:30.645 +08:00] [INFO] [apply.rs:1612] [“execute admin command”] [command=“cmd_type: BatchSplit splits { requests { split_key: 696E6F646573000000000009BBDD new_region_id: 8 new_peer_ids: 9 new_peer_ids: 10 new_peer_ids: 11 } right_derive: true }”] [index=1981] [term=6] [peer_id=6] [region_id=2]
[2023/04/07 14:03:30.645 +08:00] [INFO] [apply.rs:2470] [“split region”] [keys=“key 696E6F646573000000000009BBDD”] [region=“id: 2 region_epoch { conf_ver: 5 version: 1 } peers { id: 3 store_id: 1 } peers { id: 6 store_id: 4 } peers { id: 7 store_id: 5 }”] [peer_id=6] [region_id=2]
[2023/04/07 14:03:30.647 +08:00] [INFO] [peer.rs:3890] [“moving 0 locks to new regions”] [region_id=2]
[2023/04/07 14:03:30.647 +08:00] [INFO] [peer.rs:3985] [“insert new region”] [region=“id: 8 end_key: 696E6F646573000000000009BBDD region_epoch { conf_ver: 5 version: 2 } peers { id: 9 store_id: 1 } peers { id: 10 store_id: 4 } peers { id: 11 store_id: 5 }”] [region_id=8]
[2023/04/07 14:03:30.647 +08:00] [INFO] [peer.rs:262] [“create peer”] [peer_id=10] [region_id=8]
[2023/04/07 14:03:30.647 +08:00] [INFO] [raft.rs:2646] [“switched to configuration”] [config=“Configuration { voters: Configuration { incoming: Configuration { voters: {9, 10, 11} }, outgoing: Configuration { voters: {} } }, learners: {}, learners_next: {}, auto_leave: false }”] [raft_id=10] [region_id=8]
[2023/04/07 14:03:30.647 +08:00] [INFO] [raft.rs:1120] [“became follower at term 5”] [term=5] [raft_id=10] [region_id=8]
[2023/04/07 14:03:30.647 +08:00] [INFO] [raft.rs:384] [newRaft] [peers=“Configuration { incoming: Configuration { voters: {9, 10, 11} }, outgoing: Configuration { voters: {} } }”] [“last term”=5] [“last index”=5] [applied=5] [commit=5] [term=5] [raft_id=10] [region_id=8]
[2023/04/07 14:03:30.647 +08:00] [INFO] [raw_node.rs:315] [“RawNode created with id 10.”] [id=10] [raft_id=10] [region_id=8]
[2023/04/07 14:03:30.647 +08:00] [INFO] [raft.rs:1565] [“[logterm: 5, index: 5, vote: 0] cast vote for 9 [logterm: 5, index: 5] at term 5”] [“msg type”=MsgRequestPreVote] [term=5] [msg_index=5] [msg_term=5] [from=9] [vote=0] [log_index=5] [log_term=5] [raft_id=10] [region_id=8]
[2023/04/07 14:03:30.656 +08:00] [INFO] [raft.rs:1364] [“received a message with higher term from 9”] [“msg type”=MsgRequestVote] [message_term=6] [term=5] [from=9] [raft_id=10] [region_id=8]
[2023/04/07 14:03:30.656 +08:00] [INFO] [raft.rs:1120] [“became follower at term 6”] [term=6] [raft_id=10] [region_id=8]
[2023/04/07 14:03:30.656 +08:00] [INFO] [raft.rs:1565] [“[logterm: 5, index: 5, vote: 0] cast vote for 9 [logterm: 5, index: 5] at term 6”] [“msg type”=MsgRequestVote] [term=6] [msg_index=5] [msg_term=5] [from=9] [vote=0] [log_index=5] [log_term=5] [raft_id=10] [region_id=8]
[2023/04/07 14:03:30.658 +08:00] [INFO] [subscription_manager.rs:395] [“backup stream: on_modify_observe”] [op=“Stop { region: id: 8 end_key: 696E6F646573000000000009BBDD region_epoch { conf_ver: 5 version: 2 } peers { id: 9 store_id: 1 } peers { id: 10 store_id: 4 } peers { id: 11 store_id: 5 } }”]
[2023/04/07 14:03:30.658 +08:00] [WARN] [subscription_track.rs:143] [“trying to deregister region not registered”] [region_id=8]

2

这种错误不一定会影响集群，有可能 region 被分裂成新的了…

然后region 的信息变更后，旧的 region 肯定是无法找到了

建议继续测试

3

region是已经拆分完成了，我看pd上的信息已经更新了（/pd/api/v1/regions），但是tikv集群的任何读写全都会报上面的错误 Region invalid: null
跟踪插入debug信息，到获取region那一步基于开始结束key值能够定位到对应的regoin，也能获取到leader的store_id，但是最后Region创建是null，导致上面的报错。

4

region 的创建和调度是由 PD 来完成的，不是client …

5

不好意思，前面表述有问题，RegionStoreClient对象的创建

6

这里有个误区：

  1. 报错不一定就是 tidb 集群有问题，最好是通过dashboard ，prometheus，日志来查阅服务状态
  2. 对于这个报错，后续还持续复现么？
7
  1. 目前集群没有装tidb，dashboard我看需要sql账号，没法登陆。Prometheus上可以关注哪些指标帮助定位这块问题？
  2. 复现，我清空集群数据后下次重新插入100w条数据就出现这个问题，如只插入90w条没触发region分割就不影响使用。另外一开始我以为是region拆分后数据重新划分需要一段时间，放着过了一天查询还是这个状态。感觉拆分后就查不到region里的信息了。查询一条之前成功插入的key，这段源码最终返回的结果还是null
    Pair<Metapb.Region, Metapb.Peer> regionAndLeader = pdClient.getRegionByKey(backOffer, key);
    region = cache.putRegion(createRegion(regionAndLeader.first, regionAndLeader.second, backOffer));
8

region拆分的时候，没完成，导致插入失败

9

有没啥办法查下region是否完成拆分，当时日志最后一条提示这个，之后就没相关日志了

10

prometheus ,ganafa 查阅 PD，region 的数量的变化

如果已经插入了100W的数据，不清空接着插入呢？是否可读可写？
如果出现了 backoff，说明 region 分裂还未完成…

11

ganafa上region、leader数量都已经变成2了，三台RocksDB CPU也在一分钟内完成读写了。
region变成2后不管什么操作都无法执行，包括读取、插入、删除。
出现backoff是指日志中么，好像没出现类似的信息。

12

批写入用的是RawKVClient，这个是非事务性的，如果在插入过程中region进行拆分是否会有影响

13

这个问题我这里也遇到了，你这边解决了嘛

14

没有。我后来尝试对region进行预拆分又碰到了新的问题

16

为tikv客户端查询问题导致，使用RawKVClient查询时需增加以下设置指定
conf.setKvMode(String.valueOf(TiConfiguration.KVMode.RAW));
参见 (https://github.com/tikv/rfcs/blob/master/text/0069-api-v2.md)