br restore 恢复数据时在70%左右报错，不管是用br restore还是restore database都会这样

飞-田鼠 · 2021 年9 月 3 日 09:38

为提高效率，请提供以下信息，问题描述清晰能够更快得到解决：
【 TiDB 使用环境】
v5.0.1

【概述】场景 + 问题概述
导出数据有近300g，将其导入数据库时使用了
nohup tiup br restore db
–pd “${PDIP}:2379”
–db “test”
–storage “local:///tidb/db_bak/test”
–ratelimit 2
–checksum-concurrency 2
–concurrency 2
–log-file /tidb/db_bak/testfull.log > br_bak.log &
导出出错：
Error: rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader
Error: run /home/tidb/.tiup/components/br/v5.0.1/br (wd:/home/tidb/.tiup/data/ShpsqtW) failed: exit status 1

使用：
RESTORE DATABASE test FROM ‘local:///data/tidb/db_bak/test’
RATE_LIMIT = 20 MB/SECOND
CONCURRENCY = 2
CHECKSUM = FALSE
SEND_CREDENTIALS_TO_TIKV = FALSE;
在tidb_error.log中报错：
[2021/09/03 16:21:18.301 +08:00] [ERROR] [split_client.go:284] [“fail to split region”] [region="{ID=485041,startKey=7480000000000024FFED00000000000000F8,endKey=7480000000000024FFFA00000000000000F8,epoch=“conf_ver:5 version:40700 “,peers=“id:485042 store_id:1 ,id:485043 store_id:4 ,id:485046 store_id:5 “}”] [regionErr=“message:“EpochNotMatch [region 485041] 485042 epoch changed conf_ver: 5 version: 40705 != conf_ver: 5 version: 40700, retry later” epoch_not_match:<current_regions:<id:485041 start_key:“t\200\000\000\000\000\000$\377\362\000\000\000\000\000\000\000\370” end_key:“t\200\000\000\000\000\000$\377\372\000\000\000\000\000\000\000\370” region_epoch:<conf_ver:5 version:40705 > peers:<id:485042 store_id:1 > peers:<id:485043 store_id:4 > peers:<id:485046 store_id:5 > > > “]
[2021/09/03 17:19:53.032 +08:00] [ERROR] [kv.go:159] [“fail to load safepoint from pd”] [error=“context deadline exceeded”]
[2021/09/03 17:20:22.816 +08:00] [ERROR] [import.go:333] [“ingest file failed”] [file=”{name=78439_3900092_4493_4ceb0178f56978a56590deab48cf91067d2f4a27dfca951c383f38e8078c1d58_1630174528733_write.sst,CF=write,sha256=4fdc18205680c4361172506d75c5dd99712ebba4565935a3a0f38d75dd735c60,startKey=7480000000000015685F698000000000000003013338396537303937FF3234366261656361FF3037316237623934FF6565333261626338FF0000000000000000F70380000000000F893F,endKey=7480000000000015685F698000000000000003013366636432393361FF3065333733366630FF6336316538633263FF3761646237313132FF0000000000000000F7038000000000DBAD47,startVersion=0,endVersion=427339404500795394,totalKvs=967144,totalBytes=72535800,CRC64Xor=12204858444521534217}”] [sstMeta=”{CF=write,endKeyExclusive=false,CRC32=0,length=41114208,regionID=493201,regionEpoch=“conf_ver:5 version:40950 “,startKey=7480000000000026FF3C5F698000000000FF0000030133383965FF37303937FF323436FF6261656361FF3037FF316237623934FF65FF65333261626338FFFF0000000000000000FFF70380000000000FFF893F000000000000F9,endKey=7480000000000026FF3C5F698000000000FF0000030133666364FF32386464FF383731FF3866656439FF6530FF653934333961FF33FF31313263363463FFFF0000000000000000FFF70380000000003BFF2421000000000000F9,UUID=54d60a21-a67e-4775-96b7-d6422289961a}”] [region=”{ID=493201,startKey=7480000000000026FF3C5F698000000000FF0000030133383965FF37303937FF323436FF6261656361FF3037FF316237623934FF65FF65333261626338FFFF0000000000000000FFF70380000000000FFF893F000000000000F9,endKey=7480000000000026FF3C5F698000000000FF0000030133666364FF32393361FF306533FF3733366630FF6336FF316538633263FF37FF61646237313132FFFF0000000000000000FFF7038000000000DBFFAD47000000000000F9,epoch=“conf_ver:5 version:40950 “,peers=“id:493202 store_id:1 ,id:493203 store_id:4 ,id:493204 store_id:5 “}”] [error=“ingest error message:“stale command” stale_command:<> : [BR:KV:ErrKVIngestFailed]ingest sst failed”]
[2021/09/03 17:21:16.349 +08:00] [ERROR] [import.go:333] [“ingest file failed”] [file=”{name=1_3886668_4493_9ec30876a7a93bf2f5033b2f96331a41fc5410e0bc28842a2ea092f87a968b98_1630174524971_write.sst,CF=write,sha256=b612c95f7cfdab8d23b6d0636365083da136e0c2a8b0d3b0880b84ff9ad6ada2,startKey=7480000000000015685F698000000000000003013366636432393361FF3065333733366630FF6336316538633263FF3761646237313132FF0000000000000000F7038000000000DBAD47,endKey=7480000000000015685F698000000000000003013433383230333936FF3961336465363332FF3936323765646363FF6563336566663666FF0000000000000000F7038000000000508B8D,startVersion=0,endVersion=427339404500795394,totalKvs=499544,totalBytes=37465800,CRC64Xor=11418854896832447389}”] [sstMeta=”{CF=write,endKeyExclusive=false,CRC32=0,length=21234802,regionID=493205,regionEpoch=“conf_ver:5 version:40950 “,startKey=7480000000000026FF3C5F698000000000FF0000030133666364FF32393361FF306533FF3733366630FF6336FF316538633263FF37FF61646237313132FFFF0000000000000000FFF7038000000000DBFFAD47000000000000F9,endKey=7480000000000026FF3C5F698000000000FF0000030134333832FF30323832FF633638FF3962356239FF6663FF616365386539FF31FF64396333666134FFFF0000000000000000FFF703800000000116FFF506000000000000F9,UUID=e81fa5b4-9278-410b-b780-0429c3c8825b}”] [region=”{ID=493205,startKey=7480000000000026FF3C5F698000000000FF0000030133666364FF32393361FF306533FF3733366630FF6336FF316538633263FF37FF61646237313132FFFF0000000000000000FFF7038000000000DBFFAD47000000000000F9,endKey=7480000000000026FF3C5F698000000000FF0000030134333832FF30333936FF396133FF6465363332FF3936FF323765646363FF65FF63336566663666FFFF0000000000000000FFF703800000000050FF8B8D000000000000F9,epoch=“conf_ver:5 version:40950 “,peers=“id:493206 store_id:1 ,id:493207 store_id:4 ,id:493208 store_id:5 “}”] [error=“ingest error message:“stale command” stale_command:<> : [BR:KV:ErrKVIngestFailed]ingest sst failed”]
[2021/09/03 17:24:07.837 +08:00] [ERROR] [client.go:599] [”[pd] getTS error”] [dc-location=global] [error=”[PD:client:ErrClientGetTSO]rpc error: code = Unknown desc = [PD:tso:ErrGenerateTimestamp]generate timestamp failed, requested pd is not leader of cluster”]
[2021/09/03 17:24:11.750 +08:00] [ERROR] [client.go:599] [”[pd] getTS error"] [dc-location=global] [error="[PD:client:ErrClientGetTSO]rpc error: code = Unknown desc = [PD:tso:ErrGenerateTimestamp]generate timestamp failed, requested pd is not leader of cluster"]
[2021/09/03 17:24:11.750 +08:00] [ERROR] [pd.go:215] [“updateTS error”] [txnScope=global] [error=“rpc error: code = Unknown desc = [PD:tso:ErrGenerateTimestamp]generate timestamp failed, requested pd is not leader of cluster”]
[2021/09/03 17:24:11.753 +08:00] [ERROR] [client.go:599] ["[pd] getTS error"] [dc-location=global] [error="[PD:client:ErrClientGetTSO]rpc error: code = Unknown desc = [PD:tso:ErrGenerateTimestamp]generate timestamp failed, requested pd is not leader of cluster"]
[2021/09/03 17:24:11.753 +08:00] [ERROR] [pd.go:215] [“updateTS error”] [txnScope=global] [error=“rpc error: code = Unknown desc = [PD:tso:ErrGenerateTimestamp]generate timestamp failed, requested pd is not leader of cluster”]

[2021/09/03 17:24:20.273 +08:00] [ERROR] [pd.go:215] [“updateTS error”] [txnScope=global] [error=“rpc error: code = Unknown desc = [PD:tso:ErrGenerateTimestamp]generate timestamp failed, requested pd is not leader of cluster”]
[2021/09/03 17:24:20.665 +08:00] [ERROR] [client.go:599] ["[pd] getTS error"] [dc-location=global] [error="[PD:client:ErrClientGetTSO]rpc error: code = Unknown desc = [PD:tso:ErrGenerateTimestamp]generate timestamp failed, requested pd is not leader of cluster"]
[2021/09/03 17:24:21.047 +08:00] [ERROR] [base_client.go:166] ["[pd] failed updateMember"] [error="[PD:client:ErrClientGetLeader]get leader from [http://10.1.40.21:2379 http://10.1.40.22:2379 http://10.1.40.23:2379] error"]
[2021/09/03 17:24:21.203 +08:00] [ERROR] [client.go:599] ["[pd] getTS error"] [dc-location=global] [error="[PD:client:ErrClientGetTSO]rpc error: code = Unknown desc = [PD:tso:ErrGenerateTimestamp]generate timestamp failed, requested pd is not leader of cluster"]
[2021/09/03 17:24:21.206 +08:00] [ERROR] [base_client.go:166] ["[pd] failed updateMember"] [error="[PD:client:ErrClientGetLeader]get leader from [http://10.1.40.21:2379 http://10.1.40.22:2379 http://10.1.40.23:2379] error"]

【备份和数据迁移策略逻辑】
最终都是异常退出，请帮忙看一下了，困扰了好久。

【背景】做过哪些操作

【现象】业务和数据库现象

【问题】当前遇到的问题

【业务影响】

【TiDB 版本】

【附件】

相关日志、配置文件、Grafana 监控（https://metricstool.pingcap.com/)
TiUP Cluster Display 信息
TiUP CLuster Edit config 信息
TiDB-Overview 监控
对应模块的 Grafana 监控（如有 BR、TiDB-binlog、TiCDC 等）
对应模块日志（包含问题前后 1 小时日志）

若提问为性能优化、故障排查类问题，请下载脚本运行。终端输出的打印结果，请务必全选并复制粘贴上传。

xfworld · 2021 年9 月 3 日 11:46

从日志上看是 PD 异常导致的，硬件配置够么？然后网络都正常么？

然后恢复数据的时候，是每个tikv 节点都可以访问全部的数据么？

飞-田鼠 · 2021 年9 月 6 日 01:03

硬件配置为：3台都为16核，32g内存，网络为千m，主要是我想在这台3台机器恢复这个数据做历史同步用的，不做业务，我有设置了并发和网络限制，只要能恢复就可以了，不一定要多快。而且恢复的时候总是到70%多的时候才出问题，之前是一开始就有问题，我调了有关grpc的参数，尽量减少资源的占用以及并发度，也还是导入不了啊。恢复文件是在其中一台服务器上，然后通过nas共享给另外两台。保证tikv节点都能以相同的目录访问到全量恢复文件。

xfworld · 2021 年9 月 6 日 01:07

恢复的时候，PD 上也要恢复很多数据的，需要重建集群的元数据，以及一些regions，调度等等，但是对于网络的要求还是狠高，按照 regions 设定的默认值就是 96mb /s ，千兆网络基本上就打满了

建议切换到万兆网络在试试

飞-田鼠 · 2021 年9 月 6 日 01:43

现在可能是没有万m网络，有没有办法进行限速？减少网络开销，不要求很快恢复，看能否慢慢恢复也可以啊。另一个现象是0-70%速度还是比较快的，到了70%以后就以龟速前进，最终报错，感觉是因为什么问题让恢复慢慢变慢，或者直接卡住，另外，在restore时，可以看到restore在tidb的进程是显示在alter table更改表的auto_increment的大小，但实际上，我所有要恢复的表都是没有自增主健的，然后恢复变慢时就是有一张表在更改这个属性时，一直卡在那边，这个时候刚好就是70%左右，最后就报错了，这个是什么情况与原理呢，有无办法避免它。

xfworld · 2021 年9 月 6 日 03:01

官方的文档描述的要求就是万兆网络，毕竟不是 Mysql

飞-田鼠 · 2021 年9 月 6 日 03:05

我运行restore的时候，数据应该是有在导入的，但总是会在70-80%左右的时候导入就变得非常慢，然后最终因为pd的rpc原因挂了，第一：为什么开始的时候快，到后面变得非常慢？第二：如果是因为pd的rpc原因导致的最终报错，我是否可以只保留1台pd，让它不产生rpc错误，最终导入成功？

luancheng · 2021 年9 月 6 日 12:52

从目前的信息看，像是 PD 被打挂了，可以确认下部署的拓扑结构，是否 PD 也和 TiKV 的配置一样，都是 16c 的机器？可能还需要 PD 的日志具体确认下。

飞-田鼠 · 2021 年9 月 6 日 14:15

上面的日志就是pd的日志，后来我把pd减为1台，暂时不会报rpc的错，但是到了79％之后，导入数据变得非常慢，查看pd日志好像有个warn，grpc_server.go一直在报trying to update gc …感觉可能跟这个有关，但是又不知道为什么会报这个错引起慢，可又找不到怎么调节参数，只能继续等着看看了，到现在还在运行中，现在1个小时只能完成0.7％

luancheng · 2021 年9 月 6 日 14:33

ratelimit 参数还是去掉，这个不影响 PD。只对 TiKV 有影响

飞-田鼠 · 2021 年9 月 6 日 14:49

如果只1台pd，这个参数确实可以去掉？原本以为是网络引起的pd的rpc问题，现在只有一台了，感觉可以去掉试一下能不能加快。pd有什么优化方法没，查了半天没找到跟内存相关参数。

飞-田鼠 · 2021 年9 月 7 日 00:33

pd的日志：gc的warn为
[2021/09/07 08:32:00.992 +08:00] [WARN] [grpc_service.go:1114] [“trying to update gc safe point”] [old-safe-point=427529429571338240] [new-safe-point=0]
[2021/09/07 08:32:05.992 +08:00] [WARN] [grpc_service.go:1114] [“trying to update gc safe point”] [old-safe-point=427529429571338240] [new-safe-point=0]
[2021/09/07 08:32:10.992 +08:00] [WARN] [grpc_service.go:1114] [“trying to update gc safe point”] [old-safe-point=427529429571338240] [new-safe-point=0]
[2021/09/07 08:32:15.992 +08:00] [WARN] [grpc_service.go:1114] [“trying to update gc safe point”] [old-safe-point=427529429571338240] [new-safe-point=0]
[2021/09/07 08:32:20.992 +08:00] [WARN] [grpc_service.go:1114] [“trying to update gc safe point”] [old-safe-point=427529429571338240] [new-safe-point=0]
[2021/09/07 08:32:25.993 +08:00] [INFO] [grpc_service.go:1177] [“update service GC safe point”] [service-id=br-6e4cfdca-85b8-40db-9889-44d3062a6016] [expire-at=1630975045] [safepoint=427529429571338240]
[2021/09/07 08:32:26.017 +08:00] [WARN] [grpc_service.go:1114] [“trying to update gc safe point”] [old-safe-point=427529429571338240] [new-safe-point=0]
[2021/09/07 08:32:30.992 +08:00] [WARN] [grpc_service.go:1114] [“trying to update gc safe point”] [old-safe-point=427529429571338240] [new-safe-point=0]

luancheng · 2021 年9 月 7 日 02:44

[new-safe-point=0] 感觉是有点问题的，可以上传一份具体的 BR 日志我们看下吗？

飞-田鼠 · 2021 年9 月 7 日 02:48

br的日志都是下面的：
有看到import file done说是数据是有在导入的，没有问题，只是很慢很慢

[2021/09/07 09:00:48.084 +08:00] [INFO] [client.go:580] [“import file done”] [file="{name=4_
4083737_4606_76233333d7ccda5d6ab02ac6e5a774f24dcd274e985db638f323ff4c2caa5c80_1630175861927_
write.sst,CF=write,sha256=fbd15de4d6a0df50614ca260078e48398578be3f62d5947c6806bb44d1da2d71,s
tartKey=74800000000000164D5F698000000000000001013230323130373236FF3137313134323334FF32303030
34393330FF3331000000000000F90419AA340000000000,endKey=74800000000000164D5F698000000000000001
FB,startVersion=0,endVersion=427339404500795394,totalKvs=1120786,totalBytes=81817378,CRC64Xo
r=11610254844719535324}"] [take=46.833395816s]
[2021/09/07 09:00:51.971 +08:00] [INFO] [pd.go:390] [“pause scheduler(configs)”] [name="[bal
ance-hot-region-scheduler,balance-leader-scheduler,balance-region-scheduler]"] [cfg="{“enab
le-location-replacement”:“false”,“leader-schedule-limit”:40,“max-merge-region-keys”:0
,“max-merge-region-size”:0,“max-pending-peer-count”:2147483647,“max-snapshot-count”:40
,“region-schedule-limit”:40}"]
[2021/09/07 09:00:58.815 +08:00] [INFO] [client.go:580] [“import file done”] [file="{name=4_
4033890_4604_d34ceca8b426e539098ac3d4e3a90ddb682ec0e6fb9efc2f0c63b68200934de6_1630175864139_
write.sst,CF=write,sha256=9916760fe45100150749fbaaa9f9b9316b0a415ade62117b42d49102ac0b78ab,s
tartKey=74800000000000164D5F698000000000000002013230313731323330FF3130343135363639FF34303030
31373638FF3635000000000000F9013639323130373038FF3630343732393637FF0000000000000000F703800000
00035266BF,endKey=74800000000000164D5F698000000000000002013230313830333234FF3231333935363235
FF3230303034393331FF3635000000000000F9013639323130373032FF3238333030363531FF0000000000000000
F7038000000003420084,startVersion=0,endVersion=427339404500795394,totalKvs=612684,totalBytes
=57592296,CRC64Xor=13079666353335606677}"] [take=25.063362054s]

luancheng · 2021 年9 月 7 日 03:09

一个文件恢复耗时 46s 是非常慢的，需要相对完整的 BR 日志分析下

飞-田鼠 · 2021 年9 月 10 日 08:17

唉，看来高手都没在这边啊，pd的问题一直没能解决，不过我通过变通的方法最终成功的将数据导入了，版本为v5.0.1
先解释一下，让有相同问题的人也能得到帮助，我有生产tidb的两个库，先通过dumping想导出来，然后在新的tidb备份环境还原它，然而库的数据实在是大，一个库是500g一个库是800g，先导出小库500g的，然而为导出的时候dumping总是把tidb给搞挂掉，使用了rows和size限制，貌似没有鸟用，还说推荐呢，看来tidb的成熟度还要加强啊，唉，也可能我们的服务器配置不够吧，说实话，tidb看中的是他的横向扩展能力，简单易用，然而刚开始所要求的生产环境的tidb的配置，什么万兆网卡，什么ssd，什么64g内存，32核等等，晕了，这现有的生产系统也不那多资源啊，根本达不到，一度差点放弃。后来试用了一下，在比较一般的环境下tidb还是能跑的，只要不用它做在线业务库，当个历史库或者olap库应该可以吧。还好，我的目的比较明确，说实话，新接触tidb的人也应该都是用它来做历史库从库或者olap库吧，敢直接用生产的，要不是胆大，要不就是款爷。
闲话少说，这里也提个建议：希望tidb设计的时候能出单机版，或者内存版，也就是支持单机高cpu高内存高速ssd，做为联机在线交易使用，减少网络单的依赖，当然如果可以多机，那就支持光纤互联的那种，这样把联机的性能做到极致。然后olap就放低机器配置要求，允许低io与千兆网络集群环境使用，将其横向扩展做到极致，这样能充分满足人们对newSql的需求。
好了，下面进入正题：我用dumping实网导出失败，但在测试环境导出是没有问题的，因为测试环境数据量少，然后用tidb-lighting进行导入，然后用backend = "local"导入，官方推荐的，导入是成功了，但是，但是，居然select count() from xxx，居然是错的，与原库不同，真是大坑，这个见我另外一个贴子。count(主健)是对的，你说要tidb-lighting何用！！！后来还是使用backend = "tidb"纯sql的方式导入才正常，count()和count(主健)是一致的，但是这种方式就一个字：慢。
不过反正正式环境dumping导不出来，放弃这种导出导入了，改用br。测试了一下br导出，正式环境导出还是挺快的，因为有4台tikv，导出的时候在各台上生成备份目录，然后收集在一起就能恢复了。期间在测试环境进行几次测试，在测试环境恢复都正常，因为测试环境的数据量小，我甚至在1个tidb1个pd1个tikv的环境下也能还原成功。那就用它了，我想。
然而我还是想简单了，正式环境导出的数据一个库是150g，一个库是250g，好像导出数据会小很多，应该是有压缩了吧。好了，把备份拷到移动硬盘，准备拿到新的备份服务器上恢复，顺便说一下，对于我们这种穷人，新的备份服务器实际上配置是不高的，3台虚机，配置为：1台18核32g，1.2t机械盘，2台16核32g，1.2t机械盘，如果有看到这个配置认为我是瞎折腾，那就不要看下去了。实际上最后我是折腾成功了。
然后我把备份拷到其中一台，然后把目录共享成nfs给其它两台，一切就绪，然后：
nohup tiup br restore db
–pd “${PDIP}:2379”
–db “xxxxxx”
–storage “local:///data/tidb/db_bak/xxxxx”
–log-file /data/tidb/db_bak/xxxxfull.log > br_bak.log &
然后满心欢喜的等着，然后就出现本帖标题的问题了，试了几次，一样的问题，吐血了，这样麻烦了，好不容易拷下来的备份，恢复不了，这不扯蛋吗？然后来这边问，看来都是款爷都说我机器不行，pd搞挂了等等，没给出个什么建议来，唉，看来还是得靠自己啊。
拼命地看官方文档，看pd配置项，看tikv优化项，看grpc配置相关，想破脑袋，做了n多次的测试，最终还是还原成功了了。
以下是方法与思路：
1、既然是pd由于grpc问题leader飘走导致br进行不下去，那就不要使用多台pd，只让一台pd运行即可，避免它因为网络或者cpu相关资源leader飘走，然后为了减少pd资源，先把max-replicas改为1，只1个副本。
2、优化tikv的配置，主要是server. grpc-concurrency相关的，然后把性能测试中要求的写和读buffer也配置好内存大小。 backup. num-threads: 2，反正就减少对cpu的占用。留些资源给br。
3、br的参数相关，减少concurrency，然后不进行checksum
nohup tiup br restore db
–pd “10.1.40.22:2379”
–db “xxxxx”
–concurrency 2
–checksum=false
–storage “local:///tidb/db_bak/xxxx”
–log-file /tidb/db_bak/xxxxxfull.log > br_xxxxbak.log &
这些优化做完之后，br在执行的时候相当稳定，虽然因为库比较大，每个库恢复时间为4-5个小时，但总算中间不出错，导入成功了，查询了一下表记录，基本上都正常了，进度条只能做为参考，到100%的时候还会运行很久，大家不要着急。
然后为了追上mysql的进度，把bin-log都下载到本地，使用dm工具慢慢追赶中。
顺便说一下我用的tidb都是做为mysql-5.7的历史备份库，使用dm做数据同步的，如果这一部分有同学想讨论可以私聊。
对了，导入成功之后，记得把副本数改为3，然后增加pd节点，以防pd故障导致的数据丢失。

system · 2022 年10 月 31 日 19:17

此话题已在最后回复的 1 分钟后被自动关闭。不再允许新回复。