【故障解讀】v5.3.0 BR 備份報錯并且耗時比更新前更長

作者介紹

靳獻旗 ｜ 汽車之家 DBA
TUG 2021 年度 MVA，主要負責 MySQL、TiDB、MongoDB 的架構設計、性能調優、日常運維以及自動化
平台開發工作。
asktug 個人首頁： https://asktug.com/u/mydb/summary

問題背景

叢集版本：v5.3.0

BR 版本：v5.3.0

備份指令如下：

br backup full --pd "${pd_string}" -s "local://${bakDir}" --ratelimit 200 --log-file backup_full.log

叢集 (v4.0.10) 和 BR (v4.0.4) 統一更新到 5.3.0 版本後，BR 出現三個問題:

BR 日志有報錯資訊

BR 日志末尾雖然顯示備份成功(日志資訊類似 Full backup success summary)，但是日志中包含如下報錯資訊：

[2021/12/31 03:31:47.084 +08:00] [ERROR] [client.go:752] ["[pd] fetch pending tso requests error"] [dc-location=global] [error="[PD:client:ErrClientGetTSO]context canceled: context canceled"] [stack="github.com/tikv/pd/client.(*client).handleDispatcher\n\t/nfs/cache/mod/github.com/tikv/[email protected]/client/client.go:752"]

BR 日志顯示備份檔案大幅減小

更新前備份檔案大小：total size(MB): 4200646.35

更新後備份檔案大小：total-kv-size=2.321TB

BR 備份耗時增加一倍多

備份耗時增加一倍多，更新前備份耗時不足 2 個小時，更新後耗時高達 5 個半小時。

問題分析

從 BR 備份日志入手分析問題的原因。

更新前 BR (v4.0.4 )備份日志

[2021/12/12 23:22:01.612 +08:00] [INFO] [version.go:33] ["Welcome to Backup & Restore (BR)"]

[2021/12/12 23:22:01.612 +08:00] [INFO] [version.go:34] [BR] [release-version=v4.0.4]

[2021/12/12 23:22:01.612 +08:00] [INFO] [version.go:35] [BR] [git-hash=c91c79a8431805dcbfda2c7b2612dde6985e564c]

[2021/12/12 23:22:01.612 +08:00] [INFO] [version.go:36] [BR] [git-branch=heads/refs/tags/v4.0.4]

[2021/12/12 23:22:01.612 +08:00] [INFO] [version.go:37] [BR] [go-version=go1.13]

[2021/12/12 23:22:01.612 +08:00] [INFO] [version.go:38] [BR] [utc-build-time="2020-07-31 07:33:17"]

[2021/12/12 23:22:01.612 +08:00] [INFO] [version.go:39] [BR] [race-enabled=false]

......

[2021/12/13 01:12:12.107 +08:00] [INFO] [client.go:196] ["save backup meta"] [path=local:///dbbak/tidbFullBak/mg_tidb_full_20211212232201] [size=24088950][2021/12/13 01:12:13.021 +08:00] [INFO] [ddl.go:384] ["[ddl] DDL closed"] [ID=d57b89e9-b1c0-45a1-9659-becd4249eed3] ["take time"=198.806392ms]

[2021/12/13 01:12:13.021 +08:00] [INFO] [ddl.go:297] ["[ddl] stop DDL"] [ID=d57b89e9-b1c0-45a1-9659-becd4249eed3]

[2021/12/13 01:12:13.026 +08:00] [INFO] [domain.go:442] ["infoSyncerKeeper exited."]

[2021/12/13 01:12:13.027 +08:00] [INFO] [domain.go:612] ["domain closed"] ["take time"=203.963708ms]

[2021/12/13 01:12:13.027 +08:00] [INFO] [collector.go:61] ["Full backup Success summary: total backup ranges: 16901, total success: 16901, total failed: 0, total take(s): 6157.47, total size(MB): 4200646.35, avg speed(MB/s): 682.20,total kv: 47292061388"] ["backup checksum"=7m4.429579554s] ["backup fast checksum"=6.692480306s] ["backup total regions"=55387] [BackupTS=429738563201400858] [Size=637484128247]

更新後 BR (v5.3.0 )備份日志

[2021/12/30 22:02:02.197 +08:00] [INFO] [info.go:49] ["Welcome to Backup & Restore (BR)"] [release-version=v5.3.0] [git-hash=4a1b2e9fe5b5afb1068c56de47adb07098d768d6] [git-branch=heads/refs/tags/v5.3.0] [go-version=go1.16.4] [utc-build-time="2021-11-24 13:31:09"] [race-enabled=false]

[2021/12/30 22:02:02.197 +08:00] [INFO] [common.go:630] [arguments] [__command="br backup full"] [log-file=backup_full.log] [pd="[172.16.5.225:2379,172.16.5.226:2379,172.16.5.227:2379]"] [ratelimit=200] [storage=local:///dbbak/tidbFullBak/mg_tidb_full_20211230220202]

[2021/12/30 22:02:02.197 +08:00] [INFO] [conn.go:244] ["new mgr"] [pdAddrs=172.16.5.225:2379,172.16.5.226:2379,172.16.5.227:2379]

[2021/12/30 22:02:02.199 +08:00] [INFO] [client.go:352] ["[pd] create pd client with endpoints"] [pd-address="[172.16.5.225:2379,172.16.5.226:2379,172.16.5.227:2379]"]

[2021/12/30 22:02:02.201 +08:00] [INFO] [base_client.go:349] ["[pd] switch leader"] [new-leader=http://172.16.5.226:2379] [old-leader=][2021/12/30 22:02:02.201 +08:00] [INFO] [base_client.go:104] ["[pd] init cluster id"] [cluster-id=6857095228536967924]

[2021/12/30 22:02:02.201 +08:00] [INFO] [client.go:648] ["[pd] tso dispatcher created"] [dc-location=global]

[2021/12/30 22:02:02.203 +08:00] [INFO] [conn.go:219] ["checked alive KV stores"] [aliveStores=9] [totalStores=9]

[2021/12/30 22:02:02.203 +08:00] [INFO] [client.go:352] ["[pd] create pd client with endpoints"] [pd-address="[172.16.5.225:2379,172.16.5.226:2379,172.16.5.227:2379]"]

[2021/12/30 22:02:02.204 +08:00] [INFO] [base_client.go:349] ["[pd] switch leader"] [new-leader=http://172.16.5.226:2379] [old-leader=][2021/12/30 22:02:02.205 +08:00] [INFO] [base_client.go:104] ["[pd] init cluster id"] [cluster-id=6857095228536967924]

[2021/12/30 22:02:02.205 +08:00] [INFO] [client.go:648] ["[pd] tso dispatcher created"] [dc-location=global]

[2021/12/30 22:02:02.206 +08:00] [INFO] [client.go:93] ["new backup client"]

.......

[2021/12/31 03:31:47.083 +08:00] [ERROR] [client.go:752] ["[pd] fetch pending tso requests error"] [dc-location=global] [error="[PD:client:ErrClientGetTSO]context canceled: context canceled"] [stack="github.com/tikv/pd/client.(*client).handleDispatcher\n\t/nfs/cache/mod/github.com/tikv/[email protected]/client/client.go:752"]

[2021/12/31 03:31:47.083 +08:00] [INFO] [client.go:666] ["[pd] exit tso dispatcher"] [dc-location=global]

[2021/12/31 03:31:47.084 +08:00] [ERROR] [client.go:752] ["[pd] fetch pending tso requests error"] [dc-location=global] [error="[PD:client:ErrClientGetTSO]context canceled: context canceled"] [stack="github.com/tikv/pd/client.(*client).handleDispatcher\n\t/nfs/cache/mod/github.com/tikv/[email protected]/client/client.go:752"]

[2021/12/31 03:31:47.084 +08:00] [INFO] [client.go:666] ["[pd] exit tso dispatcher"] [dc-location=global]

[2021/12/31 03:31:47.084 +08:00] [INFO] [collector.go:66] ["Full backup success summary"] [total-ranges=59720] [ranges-succeed=59720] [ranges-failed=0] [backup-checksum=11m11.760918579s] [backup-fast-checksum=348.085778ms] [backup-total-ranges=17057] [total-take=5h29m44.887146372s] [BackupTS=430144991341838386] [total-kv=24978943921] [total-kv-size=2.321TB] [average-speed=117.3MB/s] [backup-data-size(after-compressed)=679.6GB] [Size=679630218545]

（1）是否跟日志報錯有關

更新後，日志有如下報錯資訊：

[2021/12/31 03:31:47.084 +08:00] [ERROR] [client.go:752] ["[pd] fetch pending tso requests error"] [dc-location=global] [error="[PD:client:ErrClientGetTSO]context canceled: context canceled"] [stack="github.com/tikv/pd/client.(*client).handleDispatcher\n\t/nfs/cache/mod/github.com/tikv/[email protected]/client/client.go:752"]

原因是：備份完成後，通過 PD 來啟動 GC safepoint (備份過程中 GC safepoint 是停掉的)，備份完成 context cancel 引起的這個 ERROR，後續版本會優化相關日志和邏輯。

Bug 詳情請見：https://github.com/pingcap/tidb/issues/31335

（2）是否跟備份檔案大小有關

更新前備份檔案大小是 total size(MB): 4200646.35，更新後備份檔案大小是 total-kv-size=2.321TB，不但沒增大，反而減小了，可能有以下幾種原因：

(a)是否叢集資料量減小導緻

通過分析叢集監控未發現資料量有明顯變化。

(b)是否和備份檔案壓縮有關

更新前的 v4.0.4 版本已經開啟壓縮，是以和壓縮無關。

(c)是否是日志顯示問題

這個問題是日志顯示的 bug，在 v4.0.5 版本已修複。原因是：在備份日志中重複計算備份檔案大小導緻的，第一次在 BackupRange 中，第二次在 checksum 中，應該删除第二次，并不是每個備份任務都帶有 checksum。

Bug 詳情請見：https://github.com/pingcap/br/issues/470

（3）是否跟限速有關

更新前：avg speed (MB/s): 682.20 # v4.0.4 版本

更新後：average-speed=117.3MB/s # v5.3.0 版本

使用者共計 10 個 TiKV 節點，單個 TiKV 的平均備份速度(avg speed / 10)都沒有超過 ratelimit 200 的上限，且平均備份速度差異很大。需要進行下面兩種場景的驗證：

(a)驗證限速的影響

可以對比更新前後的備份資源使用率(主要是 CPU)：在 Backup & Import -- Backup -- Backup CPU Utilization(各個版本略有不同)。使用者未提供監控，無法确認。

(b)取消限速的情況

使用者嘗試取消限速後，備份耗時恢複到更新之前的時間，最終确認是限速導緻的問題。為了避免 ratelimit 限速失敗，當配置 ratelimit 時，會将 concurrency 參數從 4 修改為 1（并且配置 ratelimit 時，concurrency 參數無法配置，預設為 1）進而降低了備份大量表的速度。

Bug 詳情請見：https://github.com/pingcap/br/issues/1007

更新後備份變慢的分析流程圖如下：

問題結論

BR 日志有報錯資訊

日志報錯資訊對備份沒影響。

Bug 詳情請見：https://github.com/pingcap/tidb/issues/31335

BR 日志顯示備份檔案大幅減小

這個問題是 bug 導緻，在 v4.0.5 版本已修複。原因是：在備份日志中重複計算備份檔案大小導緻的，第一次在 BackupRange 中，第二次在 checksum 中，應該删除第二次，并不是每個備份任務都帶有 checksum。

Bug 詳情請見：https://github.com/pingcap/br/issues/470

BR 備份耗時增加一倍多

備份耗時增加是因為使用者使用 BR 進行備份時啟用了限速(ratelimit)，導緻：為了避免 ratelimit 限速失敗，當配置 ratelimit 時，會将 concurrency 參數從 4 修改為 1（并且配置 ratelimit 時，concurrency 參數無法配置，預設為 1）進而降低了備份大量表的速度。

Bug 詳情請見：https://github.com/pingcap/br/issues/1007

優化措施

為了減少備份任務對線上叢集的影響，從 TiDB v5.4.0 起，BR 引入了自動調節功能，此功能會預設開啟。在叢集資源占用率較高的情況下，BR 可以通過該功能自動限制備份使用的資源，進而減少對叢集的影響。

需要注意的是，v5.3.x 版本的叢集，在更新到 v5.4.0 及以上版本後，自動調節功能預設關閉，需手動開啟，動态啟動或停止 BR 自動調節功能指令如下：

tikv-ctl modify-tikv-config -n backup.enable-auto-tune -v <true|false>

詳情請見官網文檔：https://docs.pingcap.com/zh/tidb/stable/br-auto-tune

【故障解讀】v5.3.0 BR 備份報錯并且耗時比更新前更長

作者介紹

問題背景

問題分析

問題結論

優化措施

相關知識

繼續閱讀

webstorm中配置git

Webstorm上配置Github和Git

Java并發程式設計一ReentrantReadWriteLock初使用

如何下載下傳blob:https://www.bilibili.com/的視訊

GitHub打開太慢,或者打不開Github,試試代理

Github通路速度慢的解決方案總彙

【考研政治】2021肖八整理（時政部分）

分享開源Cesium地形制作工具

git關聯問題解決

github 如何和 xcode 聯系起來

localstack 1.0 ga 了

【FPGA實作GA】基于FPGA的GA優化算法的設計與實作

解決方案之：DM relay 處理單元報錯

用 Canvas 編織璀璨星空圖

《2020失業潮，普通人能否出奇制勝？》筆記

開源按鍵元件Multi_Button的使用,含測試工程