作者：高振娇

背景

TiDB 的 GC 相关的问题比如 GC 的流程、参数设置、监控以及日志解析，GC 设置多大比较合适，设置过大对集群会产生什么样的影响，GC 卡住了应该从哪里排查等等一系列的问题，是笔者在使用 TiDB 过程中经常遇到的问题。

故笔者将 GC 相关的内容进行了相关的整理，一共分为 3 篇，第一篇为『GC 原理浅析』，第二篇为『GC 监控及日志解读』，而最后一篇则为『GC 处理案例 & FAQ』。

本文从案例以及 FAQ 的角度来对 GC 的问题进行分析整理，希望能够对大家对分析 GC 问题能够有所帮助，表示不严谨或者错误的地方，欢迎大家批评指正 ~~~

案例

案例 1 ：GC 持续卡在 reslove lock 阶段无法进行下去

现象描述

版本：v3.0.5
问题概述：21 日发现 GC 出现异常，通过相关监控确认，从 20 日 08:50 左右 GC 开始 GC 就已经开始出现异常，持续卡在 reslove lock 阶段无法进行下去，期间多次重启过 TiDB Server，均无效。并且伴随出现 scheduler - cleanup - duration 的报警：

排查步骤

TiDB GC Leader 日志

21 日

检查了 21日， TiDB GC Leader 的日志，TiDB Server 出现下面的持续的报错：

[2020/06/21 08:40:53.520 +08:00] [INFO] [gc_worker.go:773] ["[gc worker] start resolve locks"] [uuid=5cb18905c140033] [safePoint=417516605532274688] [concurrency=22]
[2020/06/21 08:41:53.507 +08:00] [INFO] [gc_worker.go:246] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5cb18905c140033]
............................
............................
[2020/06/21 08:51:53.510 +08:00] [INFO] [gc_worker.go:246] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5cb18905c140033]
[2020/06/21 08:52:53.547 +08:00] [INFO] [gc_worker.go:246] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5cb18905c140033]
[2020/06/21 08:53:45.989 +08:00] [ERROR] [gc_worker.go:787] ["[gc worker] resolve locks failed"] [uuid=5cb18905c140033] [safePoint=417516605532274688] [error="loadRegion from PD failed, key: \""t\"\"x80\"\"x00\"\"x00\"\"x00\"\"x00\"\"x01m\"\"xcb_i\"\"x80\"\"x00\"\"x00\"\"x00\"\"x00\"\"x00\"\"x00\"\"t\"", err: rpc error: code = Canceled desc = context canceled"] [errorVerbose="loadRegion from PD failed, key: \""t\"\"x80\"\"x00\"\"x00\"\"x00\"\"x00\"\"x01m\"\"xcb_i\"\"x80\"\"x00\"\"x00\"\"x00\"\"x00\"\"x00\"\"x00\"\"t\"", err: rpc error: code = Canceled desc = context canceled\"ngithub.com/pingcap/tidb/store/tikv.(*RegionCache).loadRegion\"n\"tgithub.com/pingcap/tidb@/store/tikv/region_cache.go:621\"ngithub.com/pingcap/tidb/store/tikv.(*RegionCache).findRegionByKey\"n\"tgithub.com/pingcap/tidb@/store/tikv/region_cache.go:358\"ngithub.com/pingcap/tidb/store/tikv.(*RegionCache).LocateKey\"n\"tgithub.com/pingcap/tidb@/store/tikv/region_cache.go:318\"ngithub.com/pingcap/tidb/store/tikv.(*RangeTaskRunner).RunOnRange\"n\"tgithub.com/pingcap/tidb@/store/tikv/range_task.go:147\"ngithub.com/pingcap/tidb/store/tikv/gcworker.(*GCWorker).resolveLocks\"n\"tgithub.com/pingcap/tidb@/store/tikv/gcworker/gc_worker.go:785\"ngithub.com/pingcap/tidb/store/tikv/gcworker.(*GCWorker).runGCJob\"n\"tgithub.com/pingcap/tidb@/store/tikv/gcworker/gc_worker.go:492\"nruntime.goexit\"n\"truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/tidb/store/tikv/gcworker.(*GCWorker).resolveLocks\"n\"tgithub.com/pingcap/tidb@/store/tikv/gcworker/gc_worker.go:787\"ngithub.com/pingcap/tidb/store/tikv/gcworker.(*GCWorker).runGCJob\"n\"tgithub.com/pingcap/tidb@/store/tikv/gcworker/gc_worker.go:492"]
……………………………………
……………………………………
[2020/06/21 10:52:46.347 +08:00] [INFO] [gc_worker.go:187] ["[gc worker] quit"] [uuid=5cb188eb3dc0006]
[2020/06/21 10:53:03.533 +08:00] [INFO] [gc_worker.go:156] ["[gc worker] start"] [uuid=5cb532ca29c0005]
[2020/06/21 10:55:03.583 +08:00] [INFO] [gc_worker.go:277] ["[gc worker] starts the whole job"] [uuid=5cb532ca29c0005] [safePoint=417518715804581888] [concurrency=22]
[2020/06/21 10:55:03.583 +08:00] [INFO] [gc_worker.go:773] ["[gc worker] start resolve locks"] [uuid=5cb532ca29c0005] [safePoint=417518715804581888] [concurrency=22]
[2020/06/21 10:56:03.541 +08:00] [INFO] [gc_worker.go:246] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5cb532ca29c0005]
……………………………………
……………………………………
[2020/06/21 16:42:41.938 +08:00] [ERROR] [gc_worker.go:787] ["[gc worker] resolve locks failed"] [uuid=5cb549336b40001] [safePoint=417520979457343488] [error="loadRegion from PD failed, key: \""t\"\"x80\"\"x00\"\"x00\"\"x00\"\"x00\"\"x01m\"\"xcb_r\"\"xf8\"\"x00\"\"x00\"\"x00\"\"x01\"\"x8f\"\"xd7;\"", err: rpc error: code = Canceled desc = context canceled"] [errorVerbose="loadRegion from PD failed, key: \""t\"\"x80\"\"x00\"\"x00\"\"x00\"\"x00\"\"x01m\"\"xcb_r\"\"xf8\"\"x00\"\"x00\"\"x00\"\"x01\"\"x8f\"\"xd7;\"", err: rpc error: code = Canceled desc = context canceled\"ngithub.com/pingcap/tidb/store/tikv.(*RegionCache).loadRegion\"n\"tgithub.com/pingcap/tidb@/store/tikv/region_cache.go:621\"ngithub.com/pingcap/tidb/store/tikv.(*RegionCache).findRegionByKey\"n\"tgithub.com/pingcap/tidb@/store/tikv/region_cache.go:358\"ngithub.com/pingcap/tidb/store/tikv.(*RegionCache).LocateKey\"n\"tgithub.com/pingcap/tidb@/store/tikv/region_cache.go:318\"ngithub.com/pingcap/tidb/store/tikv.(*RangeTaskRunner).RunOnRange\"n\"tgithub.com/pingcap/tidb@/store/tikv/range_task.go:147\"ngithub.com/pingcap/tidb/store/tikv/gcworker.(*GCWorker).resolveLocks\"n\"tgithub.com/pingcap/tidb@/store/tikv/gcworker/gc_worker.go:785\"ngithub.com/pingcap/tidb/store/tikv/gcworker.(*GCWorker).runGCJob\"n\"tgithub.com/pingcap/tidb@/store/tikv/gcworker/gc_worker.go:492\"nruntime.goexit\"n\"truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/tidb/store/tikv/gcworker.(*GCWorker).resolveLocks\"n\"tgithub.com/pingcap/tidb@/store/tikv/gcworker/gc_worker.go:787\"ngithub.com/pingcap/tidb/store/tikv/gcworker.(*GCWorker).runGCJob\"n\"tgithub.com/pingcap/tidb@/store/tikv/gcworker/gc_worker.go:492"]
[2020/06/21 16:42:54.743 +08:00] [INFO] [printer.go:41] ["Welcome to TiDB."] ["Release Version"=v3.0.5] ["Git Commit Hash"=c9000abdc216b6a02efbcc578af8be1f98ba280d] ["Git Branch"=HEAD] ["UTC Build Time"="2019-10-25 03:25:32"] [GoVersion="go version go1.13 linux/amd64"] ["Race Enabled"=false] ["Check Table Before Drop"=false] ["TiKV Min Version"=v3.0.0-60965b006877ca7234adaced7890d7b029ed1306]
……………………………………
……………………………………
[2020/06/21 16:43:00.727 +08:00] [INFO] [gc_worker.go:156] ["[gc worker] start"] [uuid=5cb582e33dc0004]
[2020/06/21 16:44:00.749 +08:00] [INFO] [gc_worker.go:277] ["[gc worker] starts the whole job"] [uuid=5cb582e33dc0004] [safePoint=417524204365938688] [concurrency=22]
[2020/06/21 16:44:00.749 +08:00] [INFO] [gc_worker.go:773] ["[gc worker] start resolve locks"] [uuid=5cb582e33dc0004] [safePoint=417524204365938688] [concurrency=22]
[2020/06/21 16:45:00.745 +08:00] [INFO] [gc_worker.go:246] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5cb582e33dc0004]
[2020/06/21 16:46:00.845 +08:00] [INFO] [gc_worker.go:246] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5cb582e33dc0004]
……………………………………
……………………………………
[2020/06/21 17:34:13.824 +08:00] [INFO] [gc_worker.go:879] ["[gc worker] region has more than limit locks"] [uuid=5cb582e33dc0004] [region=7961576] ["scan lock limit"=1024]
[2020/06/21 17:34:14.496 +08:00] [INFO] [gc_worker.go:879] ["[gc worker] region has more than limit locks"] [uuid=5cb582e33dc0004] [region=7968693] ["scan lock limit"=1024]
[2020/06/21 17:34:14.639 +08:00] [INFO] [gc_worker.go:879] ["[gc worker] region has more than limit locks"] [uuid=5cb582e33dc0004] [region=7901140] ["scan lock limit"=1024]
[2020/06/21 17:34:14.800 +08:00] [INFO] [gc_worker.go:879] ["[gc worker] region has more than limit locks"] [uuid=5cb582e33dc0004] [region=7924441] ["scan lock limit"=1024]
[2020/06/21 17:34:14.897 +08:00] [INFO] [gc_worker.go:879] ["[gc worker] region has more than limit locks"] [uuid=5cb582e33dc0004] [region=7995061] ["scan lock limit"=1024]
……………………………………
……………………………………
[2020/06/22 14:15:09.762 +08:00] [INFO] [gc_worker.go:879] ["[gc worker] region has more than limit locks"] [uuid=5cb582e33dc0004] [region=7961576] ["scan lock limit"=1024]
[2020/06/22 14:15:11.424 +08:00] [INFO] [gc_worker.go:879] ["[gc worker] region has more than limit locks"] [uuid=5cb582e33dc0004] [region=7995061] ["scan lock limit"=1024]
[2020/06/22 14:15:11.473 +08:00] [INFO] [gc_worker.go:879] ["[gc worker] region has more than limit locks"] [uuid=5cb582e33dc0004] [region=7968693] ["scan lock limit"=1024]
[2020/06/22 14:15:12.291 +08:00] [INFO] [gc_worker.go:879] ["[gc worker] region has more than limit locks"] [uuid=5cb582e33dc0004] [region=7901140] ["scan lock limit"=1024]
[2020/06/22 14:16:00.993 +08:00] [INFO] [gc_worker.go:246] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5cb582e33dc0004]

日志小结
- 21 日，TiDB Server 重启后，直到现在 reslove lock 都集中在一部分 region 中，如 7924441，7961576，7995061，7968693，7901140。
- 使用 TiDB API 检查 region 信息，发现这部分 region 都是 test_xxx_info 表的。该表在 20 日出现了较为严重的 9007 写写冲突，故在 20 日 13 点左右，将 insert 改为 insert ignore 操作：
```
curl http://{tidb_server_ip}:{tidb_server_status_port}/regions/7961576
{
  "region_id":7961576,
  "start_key":"dlAAAxxxxx/xxxxxAAAAAAAABQE0ZWE1MmQxZv9kMTU5NWM2M/8zZWY5YTImMv9kY2Vkxxxxx/xxxxxAAAAAPcDgAAAAAG6azl=",
  "end_key":"dlAAAAAxxxxx/xxxxxAAAAAAABQE0ZWE1MmQxZv9kMTU5NWM2M/8zZWY5YTImMv9kY2Vkxxxxx/xxxxxAAAAAPcDoAAAAADI2BQ=",
  "frames":[
  {
    "db_name":"clic",
    "table_name":"test_xxx_info",
    "table_id":12345,
    "is_record":false,
    "index_name":"indx_test_xxxx_md5",
    "index_values":[
    "4ea52d1fd15xxxxxxxa9f2dceda0ec",
    "28984355"
    ]
  }
  ]
}
```
- 此处怀疑可能是因为 20 号出现的写冲突集中在某几个 region 的 key 上，导致遗留的锁太多，进而出现 reslove lock 慢的情况，但是目前无法实锤。
- 报错日志中伴随 load region error，怀疑当时可能 PD 也可能存在异常，待验证。

24 日

24 日，TiDB Server GC Leader 日志如下，采集了除 gc worker 外，还采集了 lock_resolver 以及 range_task 如下:

[2020/06/24 07:36:29.404 +08:00] [INFO] [gc_worker.go:246] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5cb7b8557d40027]
[2020/06/24 07:37:29.134 +08:00] [INFO] [gc_worker.go:246] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5cb7b8557d40027]
[2020/06/24 07:47:55.855 +08:00] [INFO] [lock_resolver.go:215] ["BatchResolveLocks: lookup txn status"] ["cost time"=26m42.621156273s] ["num of txn"=1024]
[2020/06/24 07:48:28.831 +08:00] [INFO] [lock_resolver.go:215] ["BatchResolveLocks: lookup txn status"] ["cost time"=26m30.12965368s] ["num of txn"=1024]
[2020/06/24 07:48:29.103 +08:00] [INFO] [gc_worker.go:246] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5cb7b8557d40027]
[2020/06/24 07:48:35.269 +08:00] [INFO] [lock_resolver.go:215] ["BatchResolveLocks: lookup txn status"] ["cost time"=26m37.642265703s] ["num of txn"=1024]
[2020/06/24 07:48:57.773 +08:00] [INFO] [lock_resolver.go:215] ["BatchResolveLocks: lookup txn status"] ["cost time"=26m37.02897229s] ["num of txn"=1024]
[2020/06/24 07:49:13.571 +08:00] [INFO] [lock_resolver.go:215] ["BatchResolveLocks: lookup txn status"] ["cost time"=26m40.365638401s] ["num of txn"=1024]
[2020/06/24 07:49:29.104 +08:00] [INFO] [gc_worker.go:246] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5cb7b8557d40027]
[2020/06/24 07:49:38.251 +08:00] [INFO] [lock_resolver.go:215] ["BatchResolveLocks: lookup txn status"] ["cost time"=26m34.649503892s] ["num of txn"=1024]
[2020/06/24 07:49:40.482 +08:00] [INFO] [lock_resolver.go:215] ["BatchResolveLocks: lookup txn status"] ["cost time"=26m46.834123867s] ["num of txn"=1024]
……………………………………
……………………………………
[2020/06/24 08:00:29.105 +08:00] [INFO] [gc_worker.go:246] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5cb7b8557d40027]
[2020/06/24 08:01:29.107 +08:00] [INFO] [gc_worker.go:246] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5cb7b8557d40027]
[2020/06/24 08:01:48.279 +08:00] [INFO] [lock_resolver.go:215] ["BatchResolveLocks: lookup txn status"] ["cost time"=25m20.021376312s] ["num of txn"=1024]

日志小结
日志输出没有特别有价值的信息，仍卡在 reslove lock。

TiKV 监控

Grpc message count

24 日，14~18 点，看到 reslove lock 在跑，只是执行的次数不是特别频繁
21 日，00~17 点，同上

Grpc message duration

24 日，14~17 点 reslove lock duration
21 日，0~17 点 reslove lock duration

GC - reslove lock progress

24 日，14~17 点 reslove lock progress ，没有任何的变化，还卡在 reslove lock 阶段
21 日，00~17 点 reslove lock progress ，从 13:30 左右开始卡在 reslove lock 阶段
监控小结
TiKV 的监控和 TiDB 的日志比较相符，还是卡在 reslove lock 阶段。

综合分析

TiDB 的日志和 TiKV 的监控表现一致 reslove lock 阶段卡住。
TiDB 日志显示 reslove lock 都集中在一部分 region 上，并且这些 region 都是 20 日出现写写冲突严重的cert_info 表。
TiKV 的 GC 监控 reslovelocks progress 持续保持在一个水平，并且没有出现任何波动的情况，可以确定的是它不正常地卡在了个别 region 上面。

TiDB GC Leader 日志中只有这两条关于 gc 的日志在刷：

[2020/06/24 10:50:29.179 +08:00] [INFO] [gc_worker.go:246] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5cb7b8557d40027]
[2020/06/24 10:50:35.090 +08:00] [INFO] [lock_resolver.go:215] ["BatchResolveLocks: lookup txn status"] ["cost time"=23m15.448536385s] ["num of txn"=1024]
// 后者是进行 resolvelocks 请求之前打印的。如果 resolvelocks 成功的话，则应该存在另一条成功的日志，这里只可能是 resolve locks 返回了一个 regionErr。

虽然推测可能是返回了一个 regionErr 的报错，但是没有更多信息进行继续分析，此时联系了 PingCAP 官方老师协助排查，官方老师反馈当前使用的 TiDB 版本过旧，没有更多的有效日志可以参考，最终 debug 后，最终拿到了如下信息：

[2020/06/28 18:43:34.108 +08:00] [INFO] [client.go:144] ["[pd] create pd client with endpoints"] [pd-address="[10.203.137.199:2379]"]
[2020/06/28 18:43:34.112 +08:00] [INFO] [client.go:252] ["[pd] switch leader"] [new-leader=http://10.203.137.153:2379] [old-leader=]
[2020/06/28 18:43:34.112 +08:00] [INFO] [client.go:163] ["[pd] init cluster id"] [cluster-id=6755646151247435243]
[2020/06/28 18:43:34.113 +08:00] [INFO] [client.go:144] ["[pd] create pd client with endpoints"] [pd-address="[10.203.137.199:2379]"]
…………………………
…………………………
[2020/06/28 19:05:51.417 +08:00] [INFO] [client_batch.go:562] ["recycle idle connection"] [target=10.203.137.236:20160]
[2020/06/28 20:02:39.214 +08:00] [INFO] [lock_resolver.go:215] ["BatchResolveLocks: lookup txn status"] ["cost time"=59m56.324274575s] ["num of txn"=1024]
[2020/06/28 20:02:39.214 +08:00] [WARN] [region_cache.go:269] ["region cache TTL fail"] [region=8026632]
[2020/06/28 20:02:39.214 +08:00] [WARN] [region_request.go:92] ["SendReqCtx fail because can't get ctx"] [region=8026632]
[2020/06/28 20:02:39.219 +08:00] [WARN] [lock_resolver.go:245] ["BatchResolveLocks: region error"] [regionID=8026632] [regionVer=61000] [regionConfVer=740] [regionErr="epoch_not_match:<> "]
[2020/06/28 20:05:12.827 +08:00] [INFO] [lock_resolver.go:215] ["BatchResolveLocks: lookup txn status"] ["cost time"=1h2m29.730427002s] ["num of txn"=1024]
[2020/06/28 20:05:12.828 +08:00] [WARN] [region_cache.go:269] ["region cache TTL fail"] [region=8019447]
[2020/06/28 20:05:12.828 +08:00] [WARN] [region_request.go:92] ["SendReqCtx fail because can't get ctx"] [region=8019447]
[2020/06/28 20:05:12.828 +08:00] [WARN] [lock_resolver.go:245] ["BatchResolveLocks: region error"] [regionID=8019447] [regionVer=60980] [regionConfVer=683] [regionErr="epoch_not_match:<> "]

从日志可见，region cache 过期的时候有个地方会返回一个 epoch not match，意思是要求上层在这种情况下用和 epoch not match 相同的方式来处理错误。gc 慢不是 scan lock 慢而是 cleanup 慢。
这个环境在 20 号出现了大量的写冲突，并且出现了 tikv server timeout 的报错，可能残留了过多的 lock，而 scan lock 之后要对每个被 scan 到的 lock 调一次 cleanup（调用 cleanup 来清理之前残留的锁的 primary lock，没有残留锁的话本身是不需要 cleanup 调用）。然后 cleanup 耗时太久，以至于当前这个 region 已经在 region cache 里失效，于是返回前面 epoch not match ，然后整个重试，最终看到的现象是 reslove lock 被卡住了。

处理建议

调整 TiDB Server region-cache-ttl 参数，使 region cache 的过期时间拉长，由默认值 600s，调整为 86400s，重启 TiDB Server。修改此参数后，改变是 cleanup 过程中没有了 region cache 返回 epoch not match 这一步，所以就不会死循环。
在 TiKV-Details grafana dashboard 监控中添加 cleanup 监控项，观察 region-cache-ttl 调整后 GC cleanup 的情况：
- 进入 Dashboard Settings 里的这个 variables -> $command
- 然后在 Regex 里加上 |cleanup (在 v4.0 版本，可替换为 check_txn_status)
- update, save，然后刷新以后应该面板里会出现这一栏 Scheduler - cleanup
- cleanup 面板情况，可见在 29 日凌晨 1 点左右相关 metrics 趋于正常
TiKV-Details grafana dashboard 中 GC 面板中的 reslovelocks progress 开始正常的推进

改进措施

当前的机制中，如果 reslove lock 阶段 scan lock 之后要对每个被 scan 到的 lock 调一次 cleanup。如果 cleanup 耗时太久，以至于当前这个 region 已经在 region cache 里失效，于是返回前面 epoch not match ，然后整个重试，看到的现象是 GC 卡住了。

案例 2 ：GC 触发 write stall

现象描述

版本：v3.0.5
问题概述：30 日删除了共约 30T 的表，用以释放空间。在 11:45 分左右，出现 write stall 报警，并且业务的 qps 下降明显。

排查步骤

业务逻辑及压力

业务逻辑和压力出现问题前后的时间点没有明显变化，排除是因为业务侧导致 write stall。

TiKV 监控

Cluster
store size 以及 available size 都在 11:45 分有明显的变化，推测可能是大批量的删除数据的操作导致。确认后，业务方在 10:51 分左右，共计删除了 5 张大表，并且空间约 30T 左右。
Rocksdb-KV
监控小结
根据上述监控，11:45 左右 store size 变化与 altermanager 告警，rocksdb-kv write stall duration 的时间基本一致。结合删除 5 张大表的情况，推测大概率可能是 gc 导致 writecf 触发了 write stall 。
调整动作
将 rocksdb-kv 的 writecf write stall soft 以及 hard 限制分别调大到 1024G，缓解 write stall 对业务的影响。该参数可以动态调整，参考命令如下：
- 使用 tikv-ctl 调整
```
tikv-ctl --host=ip:port modify-tikv-config -m kvdb -n writecf.soft_pending_compaction_bytes_limit -v 1024GB

tikv-ctl --host=ip:port modify-tikv-config -m kvdb -n writecf.hard_pending_compaction_bytes_limit -v 1024GB
```
- 使用 SQL 进行调整
调整效果
defaultcf 以及 writecf soft 以及 hard 调整后，qps 恢复至正常水平的 ⅓。

后续排查

虽然推测是 gc 导致的，但是需要实锤。后面继续排查了下 tikv 的监控以及一个 tikv 的 log。

TiKV 监控
- Grpc
  因为是 drop 操作，gc 后，会在第二阶段 delete range 调用 unsafe_destory_range 来清理 sst 文件。查看 grpc 监控，发现在 11:45 左右确实有 unsafe_destory_range 操作，如下：
- GC
数据字典
以下是 drop 的表的信息：
TiKV 日志
查看 rocksdb-kv 的 raft 日志，有如下内容，确认是 writecf 导致 write stall:

排查结论

在 gc delete range 时，unsafe destroy range 先调用 delete_files_in_range 删除完全落在区间内的 sst ，这个过程不会触发 compaction 。此时边界处会有一些残留，因为有些 sst 一部分在区间内，一部分不在区间内，所以不能直接删掉这个文件。接下来对于这些残留会进行扫描删除，然后这里会写入删除信息到 memtable ，然后 flush ，可能引起 compaction，进而出现 write stall。出现该问题后，可以通过动态调整 pending compaction bytes 的软硬限制参数来缓解 write stall 对集群造成的影响。

FAQ

删除数据后，为什么 TiKV 的空间没有释放

在 TiDB 中，如果大量的删除数据，需要在 GC 后，观察空间是否释放，而最终空间释放的速度又与删除操作的类型相关。具体如下：

通过 Delete 的方式清理表中的数据，经历新一轮 GC 后，不会马上释放 TiKV 空间，而是在 RocksDB Compaction 后释放。
通过 Drop ，Truncate 的方式清理目标表中的数据，经历新一轮 GC 后，会在 Delete Ranges 阶段通过直接删除 sst 文件的方式马上释放空间。

如果 GC 保留的时间 tikv_gc_life_time 很长，比如 8 小时甚至更久，会对 TiDB 集群带来怎样的影响

tikv_gc_life_time 参数设置为 8 小时，表示要保留的 key 的 MVCC 版本为 8 小时，带来的好处是：

数据误删除快速恢复：如果集群误删数据但是在 GC 保留的时间内，那么可以利用 flashback table 以及 dumpling，来实现数据的快速恢复。
读取历史数据：在某些情况下，我们在排查问题时，需要查看某个 key 在特定时刻的 value。此时，可以使用 tidb_snapshot 来实现数据历史版本的读取。

同样，也会带来负面影响：

范围查询可能会带来性能下降：TiDB 的事务的实现采用了 MVCC（多版本并发控制）机制。因此，在 GC 前，一个 key 会存在多个版本，并且按照版本由新到旧进行存储。所以在进行范围扫描时，会将满足条件的 key 的历史的 MVCC 均扫描一遍。通过 Slowlog 慢查询日志也可以看到相关信息，如果 Total_keys 扫描的 key 的数量远大于 Process_keys，表示当前的 SQL 语句扫描了比较多的旧版本数据。如下示意图：

基于上述情况，建议大家根据实际的运维需求进行 GC 时间的设置。

为什么不 GC 了

不 GC 可能是 GC 相关参数设置不规范，导致 GC 无法正常开始，也有可能是其他原因导致。

人为操作导致 GC 异常

一般情况下，用户对 GC 的时间设置会手动修改，最常见的操作：

update mysql.tidb set variable_value='10m' where variable_name='tikv_gc_life_time';

有时候会漏掉单位，在修改完成之后，语句不会报错，但是 GC 不会执行。直观感觉是不断的 drop 、delete 等操作空间不回收。问题的产生一方面是用户操作问题。另外一方面是，在修改时候缺少必要的数据格式校验，官方已经在考虑完善这个问题。

长事务 block GC

从 4.0 开始，为了使持续时间较长的事务能在超过 GC Life Time 之后仍然可以正常运行，Safepoint 不会超过正在执行中的事务的开始时间 (start_ts)。即可能存在一个 session 一直持有一个比较早的 start_ts，然后 GC 会避免干掉它，最终显示的结果是不 GC。遇到这个现象时，会有以下的表现：

mysql.tidb 表中的 SafePoint 不向前推进
配有 Altermanager 的环境会出现 TiKV_GC_can_not_work gc safepoint blocked by a running session 的告警信息。

操作步骤：

确认当前环境中是否存在长时间运行的 session：

select * from information_schema.cluster_processlist where txnstart != '' order by txnstart;

+--------------------+----+------+--------------+----------+---------+------+-------+---------------------------------------------------------------------------------------------+------+----------------------------------------+
| INSTANCE           | ID | USER | HOST         | DB       | COMMAND | TIME | STATE | INFO                                                                                        | MEM  | TxnStart                               |
+--------------------+----+------+--------------+----------+---------+------+-------+---------------------------------------------------------------------------------------------+------+----------------------------------------+
| 172.16.5.189:15880 |  6 | root | 172.16.5.189 | gzj_test | Sleep   |  636 | 3     | NULL                                                                                        |    0 | 11-06 12:00:28.886(420645497441091587) |
| 172.16.5.142:15880 | 73 | root | 172.16.5.169 | NULL     | Query   |    0 | 2     | select * from information_schema.cluster_processlist where txnstart != '' order by txnstart |    0 | 11-06 12:11:09.886(420645665475395585) |
+--------------------+----+------+--------------+----------+---------+------+-------+---------------------------------------------------------------------------------------------+------+----------------------------------------+
2 rows in set (0.01 sec)

根据上面 txnstart 的查询结果，与 mysql.tidb 中的 tikv_gc_safe_point 字段的值进行比较，可以发现 conn=6 的 session 未执行完成前，tikv_gc_safe_point 并没有向前推进，从现象上看是不 GC：

MySQL [(none)]> select * from mysql.tidb;
+--------------------------+-------------------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------+
| VARIABLE_NAME            | VARIABLE_VALUE                                                                            | COMMENT                                                                                     |
+--------------------------+-------------------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------+
| bootstrapped             | True                                                                                      | Bootstrap flag. Do not delete.                                                              |
| tidb_server_version      | 47                                                                                        | Bootstrap version. Do not delete.                                                           |
| system_tz                | Asia/Shanghai                                                                             | TiDB Global System Timezone.                                                                |
| tikv_gc_leader_uuid      | 5d335b8561c000c                                                                           | Current GC worker leader UUID. (DO NOT EDIT)                                                |
| tikv_gc_leader_desc      | host:node5189, pid:20040, start at 2020-09-27 10:39:37.891861155 +0800 CST m=+0.218055497 | Host name and pid of current GC leader. (DO NOT EDIT)                                       |
| tikv_gc_leader_lease     | 20201106-12:12:37 +0800                                                                   | Current GC worker leader lease. (DO NOT EDIT)                                               |
| tikv_gc_enable           | true                                                                                      | Current GC enable status                                                                    |
| tikv_gc_run_interval     | 10m0s                                                                                     | GC run interval, at least 10m, in Go format.                                                |
| tikv_gc_life_time        | 10m0s                                                                                     | All versions within life time will not be collected by GC, at least 10m, in Go format.      |
| tikv_gc_last_run_time    | 20201106-12:10:37 +0800                                                                   | The time when last GC starts. (DO NOT EDIT)                                                 |
| tikv_gc_safe_point       | 20201106-12:00:28 +0800                                                                   | All versions after safe point can be accessed. (DO NOT EDIT)                                |
| tikv_gc_auto_concurrency | true                                                                                      | Let TiDB pick the concurrency automatically. If set false, tikv_gc_concurrency will be used |
| tikv_gc_mode             | distributed                                                                               | Mode of GC, "central" or "distributed"                                                      |
| new_collation_enabled    | False                                                                                     | If the new collations are enabled. Do not edit it.                                          |
+--------------------------+-------------------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------+
14 rows in set (0.01 sec)

与业务方确认 conn=6 ，是否符合预期
- 如果符合预期，那么需要等 conn=6 正常执行完才可以使 GC 推进下去。
- 如果不符合预期，可以使用 kill 命令将 conn=6 结束，使 GC 能够继续推进。

TiDB GC 之处理案例 & FAQ

背景

案例

案例 1 ：GC 持续卡在 reslove lock 阶段无法进行下去

现象描述

排查步骤

TiDB GC Leader 日志

21 日

24 日

TiKV 监控

Grpc message count

Grpc message duration

GC - reslove lock progress

综合分析

处理建议

改进措施

案例 2 ：GC 触发 write stall

现象描述

排查步骤

业务逻辑及压力

TiKV 监控

后续排查

排查结论

FAQ

删除数据后，为什么 TiKV 的空间没有释放

如果 GC 保留的时间 tikv_gc_life_time 很长，比如 8 小时甚至更久，会对 TiDB 集群带来怎样的影响

为什么不 GC 了

人为操作导致 GC 异常

长事务 block GC