作者: Jasper


问题背景

集群版本: v5.4.3

集群 TiKV 使用空间持续上涨, truncate 及 drop table 操作均无法正常释放空间



问题排查

  1. 从 grafana 监控观察 tikv store size 是在持续上涨的

GC异常导致空间不释放,如何通过 tikv-ctl recover-mvcc 修复_tidb

  1. dashboard 发现 unexpected resolve 报错

GC异常导致空间不释放,如何通过 tikv-ctl recover-mvcc 修复_truncate_02

  1. 根据报错详细日志查询确认 attempted_commit_ts < min_commit_ts

GC异常导致空间不释放,如何通过 tikv-ctl recover-mvcc 修复_store_03

至此确认事务状态异常导致 resolve lock 阶段不能正常进行,以至于无法进行GC。



问题解决

  1. 根据 dashboard 查找 443765878275179110 这个 ts 相关的 key,定位到 key 是 74800000000000a4255f698000000000000001013632323138383330ff3030313136303035ff3038310000000000fa0380000000004fbb7a,
  2. 跟据 key 信息定位到相关表的id 为 42021
MySQL [(none)]> select tidb_decode_key('74800000000000a4255f698000000000000001013632323138383330ff3030313136303035ff3038310000000000fa0380000000004fbb7a');
+-------------------------------------------------------------------------------------------------------------------------------------+
| tidb_decode_key('74800000000000a4255f698000000000000001013632323138383330ff3030313136303035ff3038310000000000fa0380000000004fbb7a') |
+-------------------------------------------------------------------------------------------------------------------------------------+
| {"index_id":1,"index_vals":"6221883000116005081, 5225338","table_id":42021}                                                         |
+-------------------------------------------------------------------------------------------------------------------------------------+
  • 1.
  • 2.
  • 3.
  • 4.
  • 5.
  • 6.
  1. 根据相关的key 查找到对应的 region 信息
curl http://<&tidb_ip>:10080/mvcc/hex/74800000000000a4255f698000000000000001013632323138383330ff3030313136303035ff3038310000000000fa0380000000004fbb7a 
{
 "key": "74800000000000A4255F698000000000000001013632323138383330FF3030313136303035FF3038310000000000FA0380000000004FBB7A",
 "region_id": 333744437,
 "value": {
  "info": {
   "lock": {
    "start_ts": 443765878275179110,
    "primary": "dIAAAAAAAKQlX2mAAAAAAAAABAFGU0FTMjMwOP8yNDA3MTQwN/8wNzI4OTQ4NP8wNzMyQjAwMf8AAAAAAAAAAPc=",
    "short_value": "MA=="
   },
   "writes": [
    {
     "start_ts": 443765878275179110,
     "commit_ts": 443765878550430454,
     "short_value": "MA=="
    }
   ]
  }
 }
  • 1.
  • 2.
  • 3.
  • 4.
  • 5.
  • 6.
  • 7.
  • 8.
  • 9.
  • 10.
  • 11.
  • 12.
  • 13.
  • 14.
  • 15.
  • 16.
  • 17.
  • 18.
  • 19.
  • 20.
./pd-ctl -u <&pd_ip>:<&pd-port> region key 74800000000000A4FF255F698000000000FF0000010136323231FF38383330FF303031FF3136303035FF3038FF310000000000FA03FF80000000004FBB7AFF0000000000000000F7
{
  "id": 333744437,
  "start_key": "74800000000000A4FF255F698000000000FF0000010136323231FF38303637FF353030FF3030363238FF3530FF350000000000FA03FF800000000038D8A2FF0000000000000000F7",
  "end_key": "74800000000000A4FF255F698000000000FF0000010136323231FF38383432FF363030FF3031383032FF3635FF380000000000FA03FF800000000063D7A7FF0000000000000000F7",
  "epoch": {
    "conf_ver": 15935,
    "version": 46443
  },
  "peers": [
    {
      "id": 333744438,
      "store_id": 4,
      "role_name": "Voter"
    },
    {
      "id": 333744440,
      "store_id": 6,
      "role_name": "Voter"
    },
    {
      "id": 334026539,
      "store_id": 8,
      "role_name": "Voter"
    }
  ],
  "leader": {
    "id": 333744440,
    "store_id": 6,
    "role_name": "Voter"
  },
  "written_bytes": 0,
  "read_bytes": 0,
  "written_keys": 0,
  "read_keys": 0,
  "approximate_size": 77,
  "approximate_keys": 868742
}
  • 1.
  • 2.
  • 3.
  • 4.
  • 5.
  • 6.
  • 7.
  • 8.
  • 9.
  • 10.
  • 11.
  • 12.
  • 13.
  • 14.
  • 15.
  • 16.
  • 17.
  • 18.
  • 19.
  • 20.
  • 21.
  • 22.
  • 23.
  • 24.
  • 25.
  • 26.
  • 27.
  • 28.
  • 29.
  • 30.
  • 31.
  • 32.
  • 33.
  • 34.
  • 35.
  • 36.
  • 37.
  • 38.

Region_id 为 333744437,分别存在于 4,6,8 三个store

  1. 查询对应的表是否还存在,发现表已经被 truncate,对应的key已经确认被删除,可以进行下一步操作
select * from information_schema.tables where tidb_table_id = 42021;
select * from mysql.gc_delete_range where element_id= 42021;
  • 1.
  • 2.

GC异常导致空间不释放,如何通过 tikv-ctl recover-mvcc 修复_store_04

GC异常导致空间不释放,如何通过 tikv-ctl recover-mvcc 修复_truncate_05

  1. 通过 region 信息定位到具体的 store,查询方法如下:
select store_id,address from information_schema.tikv_store_status order by 1;
  • 1.
  1. 对获取到的 key 进行编码
./tikv-ctl --to-escaped 74800000000000a4255f698000000000000001013632323138383330ff3030313136303035ff3038310000000000fa0380000000004fbb7a
  • 1.
  1. 对编码编辑到如下命令(此步骤只是准备命令,并不是真实执行)
./tikv-ctl --data-dir /DBAASDAT/tikv mvcc -k "zt\200\000\000\000\000\000\244\377%_i\200\000\000\000\000\377\000\000\001\0016221\3778830\377001\37716005\37708\3771\000\000\000\000\000\372\003\377\200\000\000\000\000O\273z\377\000\000\000\000\000\000\000\000\367" --show-cf=lock,write,default
  • 1.
  1. 分别登陆第 5 步查到的三个 tikv 实例进行操作
    关闭 tikv 进程
sh /DBAASDAT/srvMGR/service_stop.sh
  • 1.

以只读方式查询 region 中mvcc的信息

./tikv-ctl --data-dir /DBAASDAT/tikv --log-level=info recover-mvcc  --read-only -r 333744437 -p <&pd_ip>:<&pd_port>
  • 1.

  查询结果如下: 其中有一个 lock

GC异常导致空间不释放,如何通过 tikv-ctl recover-mvcc 修复_tikv_06

执行第 7 步准备的命令,进行进一步确认

./tikv-ctl --data-dir /DBAASDAT/tikv mvcc -k "zt\200\000\000\000\000\000\244\377%_i\200\000\000\000\000\377\000\000\001\0016221\3778830\377001\37716005\37708\3771\000\000\000\000\000\372\003\377\200\000\000\000\000O\273z\377\000\000\000\000\000\000\000\000\367" --show-cf=lock,write,default
  • 1.

  执行结果如下,可看到 start_ts 中的信息与 TiDB 日志中输出的问题 Key 的 start_ts 信息一致,确认其即为需要修复的 key

GC异常导致空间不释放,如何通过 tikv-ctl recover-mvcc 修复_https_07

执行修复命令

./tikv-ctl --data-dir /DBAASDAT/tikv --log-level=info recover-mvcc  -r 333744437 -p <&pd_ip>:<&pd_port>
  • 1.

  执行结果如下,可以看到对应的 lock已经消失

GC异常导致空间不释放,如何通过 tikv-ctl recover-mvcc 修复_tikv_08

修复完成后启动 tikv 进程

sh /DBAASDAT/srvMGR/service_start.sh
  • 1.
  1. 按照第8步的操作分别修复其余两个 store (操作过程略)
  2. 查看 监控发现存储空间已经正常释放

GC异常导致空间不释放,如何通过 tikv-ctl recover-mvcc 修复_https_09

  1. 查看 GC safepoint 并转换成时间,发现 safepoint 已经推进到当天
[root@50ad53bfa058 software]# curl http://<&pd_ip>:<&pd_port>/pd/api/v1/gc/safepoint
{
  "service_gc_safe_points": [
    {
      "service_id": "gc_worker",
      "expired_at": 9223372036854775807,
      "safe_point": 443931482963050496
    }
  ],
  "gc_safe_point": 443931482963050496
}


mysql>  select tidb_parse_tso(443931482963050496);
+------------------------------------+
| tidb_parse_tso(443931482963050496) |
+------------------------------------+
| 2023-08-31 06:43:34.184000         |
+------------------------------------+
1 row in set (0.00 sec)
  • 1.
  • 2.
  • 3.
  • 4.
  • 5.
  • 6.
  • 7.
  • 8.
  • 9.
  • 10.
  • 11.
  • 12.
  • 13.
  • 14.
  • 15.
  • 16.
  • 17.
  • 18.
  • 19.
  • 20.



原理解释:

GC 完整流程大概分为以下三步

  • Resolve Locks:该阶段会对所有 Region 扫描 Safepoint 之前的锁,并清理这些锁。
  • Delete Ranges:该阶段快速地删除由于 DROP TABLE/DROP INDEX 等操作产生的整区间的废弃数据。
  • Do GC:该阶段每个 TiKV 节点将会各自扫描该节点上的数据,并对每一个 key 删除其不再需要的旧版本。

本次故障是由于集群网络不稳定,长期运行中疑似引发了一个概率很低的问题,写入了错误的 lock,这个 lock 导致 GC 的 resolve lock 步骤无法成功执行。根据当前监控可以看到集群中网络延迟较高。 可以看到集群中各个节点互 ping 间断性会达到 1s 以上。

GC异常导致空间不释放,如何通过 tikv-ctl recover-mvcc 修复_https_10

引发问题过程过程概要

  1. txn1 prewrite key1,key2,key3, key1 meet network error, retry and success. key1, key2,key3 finished
  2. txn2 meet lock key1(txn1), and find all locks(key1,key2,key3) for txn1 exist, so it commit the txn1
  3. txn1's first prewrite to lock key1, success.

resolve lock 失败的原因是太晚到的那个 prewrite 请求(step3)因为是用了 async commit 的,它通过那个 tikv 节点上的 max_ts 算出了更大的 min_commit_ts 字段,而原来那个事务(txn1)早就已经用一个更小的 commit ts 提交了,所以 resolve lock 的时候 commit ts 检查出问题而导致无法正常 GC



总结

  1. Workaround

可以通过关闭全局 async commit 以及 1pc 避免此类问题的发生,关闭此参数可能会导致集群性能少许降低。

推荐保持当前配置,关闭方法如下:

set @@global.tidb_enable_async_commit = 0;
set @@global.tidb_enable_1pc = 0;
  • 1.
  • 2.
  1. 相关 issue:https://github.com/tikv/tikv/issues/11187
  2. 在日常使用过程中,要及时关注集群中 GC safepoint 相关的告警,以及tikv 磁盘使用率 如果发现异常及时介入处理,规避容量风险和集群可用性风险。