原文来源：https://tidb.net/blog/a4d6a6ca
作者：高振娇
背景
TiDB 的 GC 相关的问题比如 GC 的流程、参数设置、监控以及日志解析，GC 设置多大比较合适，设置过大对集群会产生什么样的影响，GC 卡住了应该从哪里排查等等一系列的问题，是笔者在使用 TiDB 过程中经常遇到的问题。
故笔者将 GC 相关的内容进行了相关的整理，一共分为 3 篇，第一篇为 『GC 原理浅析』，第二篇为『GC 监控及日志解读』，而最后一篇则为『GC 处理案例 & FAQ』。
本文从案例以及 FAQ 的角度来对 GC 的问题进行分析整理，希望能够对大家对分析 GC 问题能够有所帮助，表示不严谨或者错误的地方，欢迎大家批评指正 ~~~
案例
案例 1 ：GC 持续卡在 reslove lock 阶段无法进行下去
现象描述
排查步骤
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 操作：
此处怀疑可能是因为 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]
复制代码
TiKV 监控
Grpc message count
Grpc message 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 的日志在刷：
虽然推测可能是返回了一个 regionErr 的报错，但是没有更多信息进行继续分析，此时联系了 PingCAP 官方老师协助排查，官方老师反馈当前使用的 TiDB 版本过旧，没有更多的有效日志可以参考，最终 debug 后，最终拿到了如下信息：
从日志可见，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
现象描述
排查步骤
业务逻辑及压力
业务逻辑和压力出现问题前后的时间点没有明显变化，排除是因为业务侧导致 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 调整
使用 SQL 进行调整
调整效果
defaultcf 以及 writecf soft 以及 hard 调整后，qps 恢复至正常水平的 ⅓。
后续排查
虽然推测是 gc 导致的，但是需要实锤。后面继续排查了下 tikv 的监控以及一个 tikv 的 log。
排查结论
在 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 后，观察空间是否释放，而最终空间释放的速度又与删除操作的类型相关。具体如下：
如果 GC 保留的时间 tikv_gc_life_time 很长，比如 8 小时甚至更久，会对 TiDB 集群带来怎样的影响
tikv_gc_life_time 参数设置为 8 小时，表示要保留的 key 的 MVCC 版本为 8 小时，带来的好处是：
同样，也会带来负面影响：
基于上述情况，建议大家根据实际的运维需求进行 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：
根据上面 txnstart 的查询结果，与 mysql.tidb 中的 tikv_gc_safe_point 字段的值进行比较，可以发现 conn=6 的 session 未执行完成前，tikv_gc_safe_point 并没有向前推进，从现象上看是不 GC：
与业务方确认 conn=6 ，是否符合预期
如果符合预期，那么需要等 conn=6 正常执行完才可以使 GC 推进下去。
如果不符合预期，可以使用 kill 命令将 conn=6 结束，使 GC 能够继续推进。
评论